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

TestRouter Integration Flake #12736

Closed
stevekuznetsov opened this issue Jan 31, 2017 · 4 comments · Fixed by #12783 or #12860
Closed

TestRouter Integration Flake #12736

stevekuznetsov opened this issue Jan 31, 2017 · 4 comments · Fixed by #12783 or #12860
Assignees
@ramr
Labels
component/routing kind/test-flake Categorizes issue or PR as related to test flakes. priority/P1

Comments

@stevekuznetsov
Copy link
Contributor

Seen here:

--- FAIL: TestRouter (33.46s)
	router_test.go:355: TC non-secure: url 0.0.0.0 alias www.example-unsecure.com protocol http
	router_test.go:355: TC non-secure-path: url 0.0.0.0/test alias www.example-unsecure.com protocol http
	router_test.go:355: TC preferred-port: url 0.0.0.0 alias www.example-unsecure.com protocol http
	router_test.go:355: TC edge termination: url 0.0.0.0 alias www.example.com protocol https
	router_test.go:355: TC edge termination path: url 0.0.0.0/test alias www.example.com protocol https
	router_test.go:355: TC reencrypt: url 0.0.0.0 alias www.example.com protocol https
	router_test.go:355: TC reencrypt-InsecureEdgePolicy: url 0.0.0.0 alias www.example.com protocol http
	router_test.go:357: TC reencrypt-InsecureEdgePolicy failed: unavailable the entire time: endpoint not available
FAIL
Full output under the fold: 
Running TestRouter...
failed  TestRouter
I0131 10:40:05.838288   28652 router_http_server.go:358] Started, serving at 172.18.4.205:8080
I0131 10:40:05.838350   28652 router_http_server.go:358] Started, serving at 172.18.4.205:8888
I0131 10:40:05.838414   28652 router_http_server.go:358] Started, serving at 172.18.4.205:8889
I0131 10:40:05.839007   28652 router_http_server.go:390] Started, serving TLS at 172.18.4.205:8443
I0131 15:40:06.492908       1 reflector.go:185] Starting reflector *api.Service (10m0s) from github.com/openshift/origin/pkg/router/template/service_lookup.go:30
I0131 15:40:06.493648       1 reflector.go:234] Listing and watching *api.Service from github.com/openshift/origin/pkg/router/template/service_lookup.go:30
I0131 15:40:06.510192       1 router.go:140] Creating a new template router, writing to /var/lib/haproxy/router
I0131 15:40:06.510233       1 router.go:289] Template router will coalesce reloads within 1 seconds of each other
I0131 15:40:06.510244       1 router.go:347] Writing default certificate to /var/lib/haproxy/router/certs
I0131 15:40:06.510721       1 router.go:185] Reading persisted state
I0131 15:40:06.510752       1 router.go:189] Committing state
I0131 15:40:06.510757       1 router.go:390] Writing the router state
I0131 15:40:06.511337       1 router.go:395] Writing the router config
I0131 15:40:06.511625       1 router.go:211] matchPattern called with true|TRUE and 
I0131 15:40:06.511668       1 router.go:214] matchPattern returning status: false
I0131 15:40:06.511907       1 router.go:211] matchPattern called with [1-9][0-9]*(us|ms|s|m|h|d)? and 
I0131 15:40:06.511963       1 router.go:214] matchPattern returning status: false
I0131 15:40:06.511992       1 router.go:211] matchPattern called with [1-9][0-9]*(us|ms|s|m|h|d)? and 
I0131 15:40:06.512070       1 router.go:214] matchPattern returning status: false
I0131 15:40:06.512100       1 router.go:211] matchPattern called with [1-9][0-9]*(us|ms|s|m|h|d)? and 
I0131 15:40:06.512139       1 router.go:214] matchPattern returning status: false
I0131 15:40:06.512154       1 router.go:211] matchPattern called with [1-9][0-9]*(us|ms|s|m|h|d)? and 
I0131 15:40:06.512186       1 router.go:214] matchPattern returning status: false
I0131 15:40:06.512201       1 router.go:211] matchPattern called with [1-9][0-9]*(us|ms|s|m|h|d)? and 
I0131 15:40:06.512231       1 router.go:214] matchPattern returning status: false
I0131 15:40:06.512244       1 router.go:211] matchPattern called with true|TRUE and false
I0131 15:40:06.512280       1 router.go:214] matchPattern returning status: false
I0131 15:40:06.512396       1 router.go:211] matchPattern called with true|TRUE and 
I0131 15:40:06.512424       1 router.go:214] matchPattern returning status: false
I0131 15:40:06.512447       1 router.go:211] matchPattern called with true|TRUE and 
I0131 15:40:06.512469       1 router.go:214] matchPattern returning status: false
I0131 15:40:06.512538       1 router.go:400] Reloading the router
I0131 15:40:06.560356       1 router.go:475] Router reloaded:
 - Checking HAProxy /healthz on port 1936 ...
 - HAProxy port 1936 health check ok : 0 retry attempt(s).
I0131 15:40:06.560415       1 router.go:236] Router is including routes in all namespaces
I0131 15:40:06.560453       1 reflector.go:185] Starting reflector *api.Route (10m0s) from github.com/openshift/origin/pkg/router/controller/factory/factory.go:68
I0131 15:40:06.560481       1 reflector.go:185] Starting reflector *api.Endpoints (10m0s) from github.com/openshift/origin/pkg/router/controller/factory/factory.go:75
I0131 15:40:06.560504       1 controller.go:70] Running router controller
I0131 15:40:06.560513       1 reaper.go:17] Launching reaper
I0131 15:40:06.560801       1 reflector.go:234] Listing and watching *api.Route from github.com/openshift/origin/pkg/router/controller/factory/factory.go:68
I0131 15:40:06.560817       1 reflector.go:234] Listing and watching *api.Endpoints from github.com/openshift/origin/pkg/router/controller/factory/factory.go:75
I0131 15:40:06.562574       1 reflector.go:392] github.com/openshift/origin/pkg/router/controller/factory/factory.go:75: Watch close - *api.Endpoints total 1 items received
I0131 15:40:06.562705       1 plugin.go:150] Processing 1 Endpoints for Name: example (ADDED)
I0131 15:40:06.562733       1 plugin.go:153]   Subset 0 : api.EndpointSubset{Addresses:[]api.EndpointAddress{api.EndpointAddress{IP:"172.18.4.205", Hostname:"", NodeName:(*string)(nil), TargetRef:(*api.ObjectReference)(nil)}}, NotReadyAddresses:[]api.EndpointAddress(nil), Ports:[]api.EndpointPort{api.EndpointPort{Name:"", Port:8888, Protocol:"TCP"}}}
I0131 15:40:06.562826       1 plugin.go:162] Modifying endpoints for rotorouter/example
I0131 15:40:06.562855       1 controller.go:296] Router sync in progress
I0131 15:40:06.563152       1 reflector.go:392] github.com/openshift/origin/pkg/router/controller/factory/factory.go:68: Watch close - *api.Route total 1 items received
I0131 15:40:06.563247       1 controller.go:305] Processing Route: rotorouter/example -> example
I0131 15:40:06.563259       1 controller.go:306]            Alias: www.example-unsecure.com
I0131 15:40:06.563264       1 controller.go:307]            Path: 
I0131 15:40:06.563268       1 controller.go:308]            Event: ADDED
I0131 15:40:06.563275       1 router.go:129] host www.example-unsecure.com admitted
I0131 15:40:06.563397       1 unique_host.go:195] Route rotorouter/example claims www.example-unsecure.com
I0131 15:40:06.563430       1 status.go:179] has last touch <nil> for rotorouter/example
I0131 15:40:06.563462       1 status.go:269] admit: admitting route by updating status: example (true): www.example-unsecure.com
I0131 15:40:06.566526       1 router.go:686] Adding route rotorouter/example
I0131 15:40:06.566545       1 controller.go:298] Router sync complete
I0131 15:40:06.566551       1 router.go:374] Router state synchronized for the first time
I0131 15:40:06.566605       1 router.go:390] Writing the router state
I0131 15:40:06.567054       1 router.go:395] Writing the router config
I0131 15:40:06.568005       1 router.go:211] matchPattern called with true|TRUE and 
I0131 15:40:06.568083       1 router.go:214] matchPattern returning status: false
I0131 15:40:06.568771       1 router.go:211] matchPattern called with [1-9][0-9]*(us|ms|s|m|h|d)? and 
I0131 15:40:06.568843       1 router.go:214] matchPattern returning status: false
I0131 15:40:06.568868       1 router.go:211] matchPattern called with [1-9][0-9]*(us|ms|s|m|h|d)? and 
I0131 15:40:06.568911       1 router.go:214] matchPattern returning status: false
I0131 15:40:06.568935       1 router.go:211] matchPattern called with [1-9][0-9]*(us|ms|s|m|h|d)? and 
I0131 15:40:06.568972       1 router.go:214] matchPattern returning status: false
I0131 15:40:06.568992       1 router.go:211] matchPattern called with [1-9][0-9]*(us|ms|s|m|h|d)? and 
I0131 15:40:06.569034       1 router.go:214] matchPattern returning status: false
I0131 15:40:06.569056       1 router.go:211] matchPattern called with [1-9][0-9]*(us|ms|s|m|h|d)? and 
I0131 15:40:06.569092       1 router.go:214] matchPattern returning status: false
I0131 15:40:06.569111       1 router.go:211] matchPattern called with true|TRUE and false
I0131 15:40:06.569133       1 router.go:214] matchPattern returning status: false
I0131 15:40:06.569192       1 router.go:211] matchPattern called with true|TRUE and 
I0131 15:40:06.569217       1 router.go:214] matchPattern returning status: false
I0131 15:40:06.569248       1 router.go:211] matchPattern called with true|TRUE and 
I0131 15:40:06.569298       1 router.go:214] matchPattern returning status: false
I0131 15:40:06.569455       1 router.go:211] matchPattern called with roundrobin|leastconn|source and 
I0131 15:40:06.569526       1 router.go:214] matchPattern returning status: false
I0131 15:40:06.569576       1 router.go:211] matchPattern called with true|TRUE and 
I0131 15:40:06.569619       1 router.go:214] matchPattern returning status: false
I0131 15:40:06.569645       1 router.go:211] matchPattern called with true|TRUE and 
I0131 15:40:06.569673       1 router.go:214] matchPattern returning status: false
I0131 15:40:06.569761       1 router.go:211] matchPattern called with [1-9][0-9]*(us|ms|s|m|h|d)? and 
I0131 15:40:06.569915       1 router.go:214] matchPattern returning status: false
I0131 15:40:06.570179       1 router.go:400] Reloading the router
I0131 15:40:06.593494       1 reaper.go:24] Signal received: child exited
I0131 15:40:06.593550       1 reaper.go:32] Reaped process with pid 30
I0131 15:40:06.602492       1 router.go:475] Router reloaded:
 - Checking HAProxy /healthz on port 1936 ...
 - HAProxy port 1936 health check ok : 0 retry attempt(s).
I0131 15:40:06.602519       1 reaper.go:24] Signal received: child exited
I0131 15:40:06.663850       1 reflector.go:392] github.com/openshift/origin/pkg/router/controller/factory/factory.go:68: Watch close - *api.Route total 1 items received
I0131 15:40:06.663850       1 reflector.go:392] github.com/openshift/origin/pkg/router/controller/factory/factory.go:75: Watch close - *api.Endpoints total 1 items received
I0131 15:40:06.664030       1 controller.go:305] Processing Route: rotorouter/example -> example
I0131 15:40:06.664049       1 controller.go:306]            Alias: www.example-unsecure.com
I0131 15:40:06.664056       1 controller.go:307]            Path: 
I0131 15:40:06.664062       1 controller.go:308]            Event: DELETED
I0131 15:40:06.664073       1 router.go:129] host www.example-unsecure.com admitted
I0131 15:40:06.664119       1 unique_host.go:211] Deleting routes for rotorouter/example
I0131 15:40:06.664140       1 plugin.go:190] Deleting route rotorouter/example
I0131 15:40:06.664190       1 plugin.go:150] Processing 0 Endpoints for Name: example (MODIFIED)
I0131 15:40:06.664206       1 plugin.go:162] Modifying endpoints for rotorouter/example
I0131 15:40:06.664628       1 reflector.go:392] github.com/openshift/origin/pkg/router/controller/factory/factory.go:68: Watch close - *api.Route total 1 items received
I0131 15:40:06.664729       1 reflector.go:392] github.com/openshift/origin/pkg/router/controller/factory/factory.go:75: Watch close - *api.Endpoints total 1 items received
I0131 15:40:06.664774       1 controller.go:305] Processing Route: rotorouter/example-path -> example-path
I0131 15:40:06.664783       1 controller.go:306]            Alias: www.example-unsecure.com
I0131 15:40:06.664790       1 controller.go:307]            Path: /test
I0131 15:40:06.664795       1 controller.go:308]            Event: ADDED
I0131 15:40:06.664804       1 router.go:129] host www.example-unsecure.com admitted
I0131 15:40:06.664834       1 unique_host.go:195] Route rotorouter/example-path claims www.example-unsecure.com
I0131 15:40:06.664843       1 status.go:179] has last touch <nil> for rotorouter/example-path
I0131 15:40:06.664868       1 status.go:269] admit: admitting route by updating status: example-path (true): www.example-unsecure.com
I0131 15:40:06.665576       1 router.go:686] Adding route rotorouter/example-path
I0131 15:40:06.665598       1 router.go:692] Creating new frontend for key: rotorouter/example-path
I0131 15:40:06.665624       1 plugin.go:150] Processing 1 Endpoints for Name: example-path (ADDED)
I0131 15:40:06.665637       1 plugin.go:153]   Subset 0 : api.EndpointSubset{Addresses:[]api.EndpointAddress{api.EndpointAddress{IP:"172.18.4.205", Hostname:"", NodeName:(*string)(nil), TargetRef:(*api.ObjectReference)(nil)}}, NotReadyAddresses:[]api.EndpointAddress(nil), Ports:[]api.EndpointPort{api.EndpointPort{Name:"", Port:8888, Protocol:"TCP"}}}
I0131 15:40:06.665668       1 plugin.go:162] Modifying endpoints for rotorouter/example-path
I0131 15:40:06.765474       1 reflector.go:392] github.com/openshift/origin/pkg/router/controller/factory/factory.go:68: Watch close - *api.Route total 1 items received
I0131 15:40:06.765516       1 reflector.go:392] github.com/openshift/origin/pkg/router/controller/factory/factory.go:75: Watch close - *api.Endpoints total 1 items received
I0131 15:40:06.765612       1 controller.go:305] Processing Route: rotorouter/example-path -> example-path
I0131 15:40:06.765625       1 controller.go:306]            Alias: www.example-unsecure.com
I0131 15:40:06.765629       1 controller.go:307]            Path: /test
I0131 15:40:06.765633       1 controller.go:308]            Event: DELETED
I0131 15:40:06.765641       1 router.go:129] host www.example-unsecure.com admitted
I0131 15:40:06.765658       1 unique_host.go:211] Deleting routes for rotorouter/example-path
I0131 15:40:06.765664       1 plugin.go:190] Deleting route rotorouter/example-path
I0131 15:40:06.765701       1 plugin.go:150] Processing 0 Endpoints for Name: example-path (MODIFIED)
I0131 15:40:06.765713       1 plugin.go:162] Modifying endpoints for rotorouter/example-path
I0131 15:40:06.766140       1 reflector.go:392] github.com/openshift/origin/pkg/router/controller/factory/factory.go:75: Watch close - *api.Endpoints total 1 items received
I0131 15:40:06.766291       1 plugin.go:150] Processing 2 Endpoints for Name: example-preferred-port (ADDED)
I0131 15:40:06.766303       1 plugin.go:153]   Subset 0 : api.EndpointSubset{Addresses:[]api.EndpointAddress{api.EndpointAddress{IP:"172.18.4.205", Hostname:"", NodeName:(*string)(nil), TargetRef:(*api.ObjectReference)(nil)}}, NotReadyAddresses:[]api.EndpointAddress(nil), Ports:[]api.EndpointPort{api.EndpointPort{Name:"", Port:8889, Protocol:"TCP"}}}
I0131 15:40:06.766326       1 plugin.go:153]   Subset 1 : api.EndpointSubset{Addresses:[]api.EndpointAddress{api.EndpointAddress{IP:"172.18.4.205", Hostname:"", NodeName:(*string)(nil), TargetRef:(*api.ObjectReference)(nil)}}, NotReadyAddresses:[]api.EndpointAddress(nil), Ports:[]api.EndpointPort{api.EndpointPort{Name:"", Port:8888, Protocol:"TCP"}}}
I0131 15:40:06.766349       1 plugin.go:162] Modifying endpoints for rotorouter/example-preferred-port
I0131 15:40:06.766696       1 reflector.go:392] github.com/openshift/origin/pkg/router/controller/factory/factory.go:68: Watch close - *api.Route total 1 items received
I0131 15:40:06.766844       1 controller.go:305] Processing Route: rotorouter/example-preferred-port -> example-preferred-port
I0131 15:40:06.766855       1 controller.go:306]            Alias: www.example-unsecure.com
I0131 15:40:06.766861       1 controller.go:307]            Path: 
I0131 15:40:06.766867       1 controller.go:308]            Event: ADDED
I0131 15:40:06.766876       1 router.go:129] host www.example-unsecure.com admitted
I0131 15:40:06.766910       1 unique_host.go:195] Route rotorouter/example-preferred-port claims www.example-unsecure.com
I0131 15:40:06.766923       1 status.go:179] has last touch <nil> for rotorouter/example-preferred-port
I0131 15:40:06.766944       1 status.go:269] admit: admitting route by updating status: example-preferred-port (true): www.example-unsecure.com
I0131 15:40:06.767622       1 router.go:686] Adding route rotorouter/example-preferred-port
I0131 15:40:06.867102       1 reflector.go:392] github.com/openshift/origin/pkg/router/controller/factory/factory.go:68: Watch close - *api.Route total 1 items received
I0131 15:40:06.867122       1 plugin.go:150] Processing 0 Endpoints for Name: example-preferred-port (MODIFIED)
I0131 15:40:06.867135       1 plugin.go:162] Modifying endpoints for rotorouter/example-preferred-port
I0131 15:40:06.867169       1 controller.go:305] Processing Route: rotorouter/example-preferred-port -> example-preferred-port
I0131 15:40:06.867180       1 controller.go:306]            Alias: www.example-unsecure.com
I0131 15:40:06.867186       1 controller.go:307]            Path: 
I0131 15:40:06.867192       1 controller.go:308]            Event: DELETED
I0131 15:40:06.867200       1 router.go:129] host www.example-unsecure.com admitted
I0131 15:40:06.867108       1 reflector.go:392] github.com/openshift/origin/pkg/router/controller/factory/factory.go:75: Watch close - *api.Endpoints total 1 items received
I0131 15:40:06.867223       1 unique_host.go:211] Deleting routes for rotorouter/example-preferred-port
I0131 15:40:06.867234       1 plugin.go:190] Deleting route rotorouter/example-preferred-port
I0131 15:40:06.867717       1 reflector.go:392] github.com/openshift/origin/pkg/router/controller/factory/factory.go:75: Watch close - *api.Endpoints total 1 items received
I0131 15:40:06.867824       1 plugin.go:150] Processing 1 Endpoints for Name: example-edge (ADDED)
I0131 15:40:06.867835       1 plugin.go:153]   Subset 0 : api.EndpointSubset{Addresses:[]api.EndpointAddress{api.EndpointAddress{IP:"172.18.4.205", Hostname:"", NodeName:(*string)(nil), TargetRef:(*api.ObjectReference)(nil)}}, NotReadyAddresses:[]api.EndpointAddress(nil), Ports:[]api.EndpointPort{api.EndpointPort{Name:"", Port:8888, Protocol:"TCP"}}}
I0131 15:40:06.867857       1 plugin.go:162] Modifying endpoints for rotorouter/example-edge
I0131 15:40:06.868309       1 reflector.go:392] github.com/openshift/origin/pkg/router/controller/factory/factory.go:68: Watch close - *api.Route total 1 items received
I0131 15:40:06.868444       1 controller.go:305] Processing Route: rotorouter/example-edge -> example-edge
I0131 15:40:06.868458       1 controller.go:306]            Alias: www.example.com
I0131 15:40:06.868464       1 controller.go:307]            Path: 
I0131 15:40:06.868469       1 controller.go:308]            Event: ADDED
I0131 15:40:06.868475       1 router.go:129] host www.example.com admitted
I0131 15:40:06.868497       1 unique_host.go:195] Route rotorouter/example-edge claims www.example.com
I0131 15:40:06.869634       1 status.go:179] has last touch <nil> for rotorouter/example-edge
I0131 15:40:06.869665       1 status.go:269] admit: admitting route by updating status: example-edge (true): www.example.com
I0131 15:40:06.870323       1 router.go:686] Adding route rotorouter/example-edge
I0131 15:40:07.510427       1 router.go:390] Writing the router state
I0131 15:40:07.510816       1 router.go:395] Writing the router config
I0131 15:40:07.515965       1 router.go:211] matchPattern called with [1-9][0-9]*(us|ms|s|m|h|d)? and 
I0131 15:40:07.516060       1 router.go:214] matchPattern returning status: false
I0131 15:40:07.516101       1 router.go:211] matchPattern called with [1-9][0-9]*(us|ms|s|m|h|d)? and 
I0131 15:40:07.516178       1 router.go:214] matchPattern returning status: false
I0131 15:40:07.516204       1 router.go:211] matchPattern called with [1-9][0-9]*(us|ms|s|m|h|d)? and 
I0131 15:40:07.516272       1 router.go:214] matchPattern returning status: false
I0131 15:40:07.516294       1 router.go:211] matchPattern called with [1-9][0-9]*(us|ms|s|m|h|d)? and 
I0131 15:40:07.516346       1 router.go:214] matchPattern returning status: false
I0131 15:40:07.516387       1 router.go:211] matchPattern called with [1-9][0-9]*(us|ms|s|m|h|d)? and 
I0131 15:40:07.516450       1 router.go:214] matchPattern returning status: false
I0131 15:40:07.516472       1 router.go:211] matchPattern called with true|TRUE and false
I0131 15:40:07.516496       1 router.go:214] matchPattern returning status: false
I0131 15:40:07.516581       1 router.go:211] matchPattern called with true|TRUE and 
I0131 15:40:07.516637       1 router.go:214] matchPattern returning status: false
I0131 15:40:07.516667       1 router.go:211] matchPattern called with true|TRUE and 
I0131 15:40:07.516696       1 router.go:214] matchPattern returning status: false
I0131 15:40:07.516815       1 router.go:211] matchPattern called with roundrobin|leastconn|source and 
I0131 15:40:07.516862       1 router.go:214] matchPattern returning status: false
I0131 15:40:07.516895       1 router.go:211] matchPattern called with true|TRUE and 
I0131 15:40:07.516925       1 router.go:214] matchPattern returning status: false
I0131 15:40:07.516943       1 router.go:211] matchPattern called with true|TRUE and 
I0131 15:40:07.516967       1 router.go:214] matchPattern returning status: false
I0131 15:40:07.517037       1 router.go:211] matchPattern called with [1-9][0-9]*(us|ms|s|m|h|d)? and 
I0131 15:40:07.517106       1 router.go:214] matchPattern returning status: false
I0131 15:40:07.517907       1 router.go:211] matchPattern called with true|TRUE and 
I0131 15:40:07.517940       1 router.go:214] matchPattern returning status: false
I0131 15:40:07.518087       1 router.go:400] Reloading the router
I0131 15:40:07.551868       1 router.go:475] Router reloaded:
 - Checking HAProxy /healthz on port 1936 ...
 - HAProxy port 1936 health check ok : 0 retry attempt(s).
I0131 15:40:07.551879       1 reaper.go:24] Signal received: child exited
I0131 15:40:07.572952       1 reflector.go:392] github.com/openshift/origin/pkg/router/controller/factory/factory.go:75: Watch close - *api.Endpoints total 1 items received
I0131 15:40:07.573158       1 reflector.go:392] github.com/openshift/origin/pkg/router/controller/factory/factory.go:68: Watch close - *api.Route total 1 items received
I0131 15:40:07.573158       1 plugin.go:150] Processing 0 Endpoints for Name: example-edge (MODIFIED)
I0131 15:40:07.573310       1 plugin.go:162] Modifying endpoints for rotorouter/example-edge
I0131 15:40:07.573344       1 controller.go:305] Processing Route: rotorouter/example-edge -> example-edge
I0131 15:40:07.573356       1 controller.go:306]            Alias: www.example.com
I0131 15:40:07.573362       1 controller.go:307]            Path: 
I0131 15:40:07.573369       1 controller.go:308]            Event: DELETED
I0131 15:40:07.573395       1 router.go:129] host www.example.com admitted
I0131 15:40:07.573432       1 unique_host.go:211] Deleting routes for rotorouter/example-edge
I0131 15:40:07.574730       1 plugin.go:190] Deleting route rotorouter/example-edge
I0131 15:40:07.575519       1 reflector.go:392] github.com/openshift/origin/pkg/router/controller/factory/factory.go:75: Watch close - *api.Endpoints total 1 items received
I0131 15:40:07.575621       1 plugin.go:150] Processing 1 Endpoints for Name: example-edge-path (ADDED)
I0131 15:40:07.575629       1 plugin.go:153]   Subset 0 : api.EndpointSubset{Addresses:[]api.EndpointAddress{api.EndpointAddress{IP:"172.18.4.205", Hostname:"", NodeName:(*string)(nil), TargetRef:(*api.ObjectReference)(nil)}}, NotReadyAddresses:[]api.EndpointAddress(nil), Ports:[]api.EndpointPort{api.EndpointPort{Name:"", Port:8888, Protocol:"TCP"}}}
I0131 15:40:07.575655       1 plugin.go:162] Modifying endpoints for rotorouter/example-edge-path
I0131 15:40:07.575951       1 reflector.go:392] github.com/openshift/origin/pkg/router/controller/factory/factory.go:68: Watch close - *api.Route total 1 items received
I0131 15:40:07.576054       1 controller.go:305] Processing Route: rotorouter/example-edge-path -> example-edge-path
I0131 15:40:07.576060       1 controller.go:306]            Alias: www.example.com
I0131 15:40:07.576064       1 controller.go:307]            Path: /test
I0131 15:40:07.576068       1 controller.go:308]            Event: ADDED
I0131 15:40:07.576075       1 router.go:129] host www.example.com admitted
I0131 15:40:07.576101       1 unique_host.go:195] Route rotorouter/example-edge-path claims www.example.com
I0131 15:40:07.577083       1 status.go:179] has last touch <nil> for rotorouter/example-edge-path
I0131 15:40:07.577103       1 status.go:269] admit: admitting route by updating status: example-edge-path (true): www.example.com
I0131 15:40:07.577962       1 router.go:686] Adding route rotorouter/example-edge-path
I0131 15:40:07.679867       1 reflector.go:392] github.com/openshift/origin/pkg/router/controller/factory/factory.go:75: Watch close - *api.Endpoints total 1 items received
I0131 15:40:07.680090       1 plugin.go:150] Processing 0 Endpoints for Name: example-edge-path (MODIFIED)
I0131 15:40:07.680107       1 plugin.go:162] Modifying endpoints for rotorouter/example-edge-path
I0131 15:40:07.680273       1 reflector.go:392] github.com/openshift/origin/pkg/router/controller/factory/factory.go:68: Watch close - *api.Route total 1 items received
I0131 15:40:07.680447       1 controller.go:305] Processing Route: rotorouter/example-edge-path -> example-edge-path
I0131 15:40:07.680460       1 controller.go:306]            Alias: www.example.com
I0131 15:40:07.680466       1 controller.go:307]            Path: /test
I0131 15:40:07.680472       1 controller.go:308]            Event: DELETED
I0131 15:40:07.680488       1 router.go:129] host www.example.com admitted
I0131 15:40:07.680534       1 unique_host.go:211] Deleting routes for rotorouter/example-edge-path
I0131 15:40:07.680633       1 reflector.go:392] github.com/openshift/origin/pkg/router/controller/factory/factory.go:75: Watch close - *api.Endpoints total 1 items received
I0131 15:40:07.681866       1 plugin.go:190] Deleting route rotorouter/example-edge-path
I0131 15:40:07.681897       1 certmanager.go:163] attempted to delete file /var/lib/haproxy/router/certs/rotorouter_example-edge-path.pem but it does not exist
I0131 15:40:07.681922       1 plugin.go:150] Processing 1 Endpoints for Name: example-reencrypt (ADDED)
I0131 15:40:07.681929       1 plugin.go:153]   Subset 0 : api.EndpointSubset{Addresses:[]api.EndpointAddress{api.EndpointAddress{IP:"172.18.4.205", Hostname:"", NodeName:(*string)(nil), TargetRef:(*api.ObjectReference)(nil)}}, NotReadyAddresses:[]api.EndpointAddress(nil), Ports:[]api.EndpointPort{api.EndpointPort{Name:"", Port:8443, Protocol:"TCP"}}}
I0131 15:40:07.681948       1 plugin.go:162] Modifying endpoints for rotorouter/example-reencrypt
I0131 15:40:07.682809       1 reflector.go:392] github.com/openshift/origin/pkg/router/controller/factory/factory.go:68: Watch close - *api.Route total 1 items received
I0131 15:40:07.682910       1 controller.go:305] Processing Route: rotorouter/example-reencrypt -> example-reencrypt
I0131 15:40:07.682924       1 controller.go:306]            Alias: www.example.com
I0131 15:40:07.682930       1 controller.go:307]            Path: 
I0131 15:40:07.682936       1 controller.go:308]            Event: ADDED
I0131 15:40:07.682945       1 router.go:129] host www.example.com admitted
I0131 15:40:07.682977       1 unique_host.go:195] Route rotorouter/example-reencrypt claims www.example.com
I0131 15:40:07.684394       1 status.go:179] has last touch <nil> for rotorouter/example-reencrypt
I0131 15:40:07.684422       1 status.go:269] admit: admitting route by updating status: example-reencrypt (true): www.example.com
I0131 15:40:07.685391       1 router.go:686] Adding route rotorouter/example-reencrypt
I0131 15:40:08.510516       1 router.go:390] Writing the router state
I0131 15:40:08.510984       1 router.go:395] Writing the router config
I0131 15:40:08.511740       1 router.go:211] matchPattern called with [1-9][0-9]*(us|ms|s|m|h|d)? and 
I0131 15:40:08.511843       1 router.go:214] matchPattern returning status: false
I0131 15:40:08.511881       1 router.go:211] matchPattern called with [1-9][0-9]*(us|ms|s|m|h|d)? and 
I0131 15:40:08.511948       1 router.go:214] matchPattern returning status: false
I0131 15:40:08.511982       1 router.go:211] matchPattern called with [1-9][0-9]*(us|ms|s|m|h|d)? and 
I0131 15:40:08.512048       1 router.go:214] matchPattern returning status: false
I0131 15:40:08.512078       1 router.go:211] matchPattern called with [1-9][0-9]*(us|ms|s|m|h|d)? and 
I0131 15:40:08.512169       1 router.go:214] matchPattern returning status: false
I0131 15:40:08.512202       1 router.go:211] matchPattern called with [1-9][0-9]*(us|ms|s|m|h|d)? and 
I0131 15:40:08.512276       1 router.go:214] matchPattern returning status: false
I0131 15:40:08.512310       1 router.go:211] matchPattern called with true|TRUE and false
I0131 15:40:08.512345       1 router.go:214] matchPattern returning status: false
I0131 15:40:08.512478       1 router.go:211] matchPattern called with true|TRUE and 
I0131 15:40:08.512526       1 router.go:214] matchPattern returning status: false
I0131 15:40:08.512570       1 router.go:211] matchPattern called with true|TRUE and 
I0131 15:40:08.512611       1 router.go:214] matchPattern returning status: false
I0131 15:40:08.512831       1 router.go:211] matchPattern called with roundrobin|leastconn|source and 
I0131 15:40:08.512910       1 router.go:214] matchPattern returning status: false
I0131 15:40:08.512961       1 router.go:211] matchPattern called with true|TRUE and 
I0131 15:40:08.513011       1 router.go:214] matchPattern returning status: false
I0131 15:40:08.513045       1 router.go:211] matchPattern called with true|TRUE and 
I0131 15:40:08.513091       1 router.go:214] matchPattern returning status: false
I0131 15:40:08.513182       1 router.go:211] matchPattern called with [1-9][0-9]*(us|ms|s|m|h|d)? and 
I0131 15:40:08.513260       1 router.go:214] matchPattern returning status: false
I0131 15:40:08.514342       1 router.go:211] matchPattern called with true|TRUE and 
I0131 15:40:08.514403       1 router.go:214] matchPattern returning status: false
I0131 15:40:08.514649       1 router.go:400] Reloading the router
I0131 15:40:08.551908       1 router.go:475] Router reloaded:
 - Checking HAProxy /healthz on port 1936 ...
 - HAProxy port 1936 health check ok : 0 retry attempt(s).
I0131 15:40:08.551911       1 reaper.go:24] Signal received: child exited
I0131 15:40:08.587336       1 reflector.go:392] github.com/openshift/origin/pkg/router/controller/factory/factory.go:75: Watch close - *api.Endpoints total 1 items received
E0131 15:40:08.588072       1 runtime.go:64] Observed a panic: "Invalid state transition: MODIFIED -> ADDED" (Invalid state transition: MODIFIED -> ADDED)
/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/vendor/k8s.io/kubernetes/pkg/util/runtime/runtime.go:70
/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/vendor/k8s.io/kubernetes/pkg/util/runtime/runtime.go:63
/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/vendor/k8s.io/kubernetes/pkg/util/runtime/runtime.go:49
/usr/local/go/src/runtime/asm_amd64.s:479
/usr/local/go/src/runtime/panic.go:458
/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/pkg/client/cache/eventqueue.go:132
/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/pkg/client/cache/eventqueue.go:196
/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/vendor/k8s.io/kubernetes/pkg/client/cache/reflector.go:370
/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/vendor/k8s.io/kubernetes/pkg/client/cache/reflector.go:317
/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/vendor/k8s.io/kubernetes/pkg/client/cache/reflector.go:187
/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/vendor/k8s.io/kubernetes/pkg/util/wait/wait.go:96
/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/vendor/k8s.io/kubernetes/pkg/util/wait/wait.go:97
/go/src/github.com/openshift/origin/_output/local/go/src/github.com/openshift/origin/vendor/k8s.io/kubernetes/pkg/util/wait/wait.go:52
/usr/local/go/src/runtime/asm_amd64.s:2086
I0131 15:40:08.588088       1 reflector.go:392] github.com/openshift/origin/pkg/router/controller/factory/factory.go:68: Watch close - *api.Route total 1 items received
I0131 15:40:08.588216       1 controller.go:305] Processing Route: rotorouter/example-reencrypt -> example-reencrypt
I0131 15:40:08.588237       1 controller.go:306]            Alias: www.example.com
I0131 15:40:08.588244       1 controller.go:307]            Path: 
I0131 15:40:08.588251       1 controller.go:308]            Event: DELETED
I0131 15:40:08.588266       1 router.go:129] host www.example.com admitted
I0131 15:40:08.588300       1 unique_host.go:211] Deleting routes for rotorouter/example-reencrypt
I0131 15:40:08.589225       1 reflector.go:392] github.com/openshift/origin/pkg/router/controller/factory/factory.go:68: Watch close - *api.Route total 1 items received
I0131 15:40:08.590164       1 plugin.go:190] Deleting route rotorouter/example-reencrypt
I0131 15:40:08.590337       1 controller.go:305] Processing Route: rotorouter/example-reencrypt -> example-reencrypt
I0131 15:40:08.590346       1 controller.go:306]            Alias: www.example.com
I0131 15:40:08.590350       1 controller.go:307]            Path: 
I0131 15:40:08.590354       1 controller.go:308]            Event: ADDED
I0131 15:40:08.590363       1 router.go:129] host www.example.com admitted
I0131 15:40:08.590400       1 unique_host.go:195] Route rotorouter/example-reencrypt claims www.example.com
I0131 15:40:08.591942       1 status.go:179] has last touch <nil> for rotorouter/example-reencrypt
I0131 15:40:08.591971       1 status.go:269] admit: admitting route by updating status: example-reencrypt (true): www.example.com
I0131 15:40:08.592618       1 router.go:686] Adding route rotorouter/example-reencrypt
I0131 15:40:08.592666       1 plugin.go:150] Processing 0 Endpoints for Name: example-reencrypt (MODIFIED)
I0131 15:40:08.592679       1 plugin.go:162] Modifying endpoints for rotorouter/example-reencrypt
I0131 15:40:09.510457       1 router.go:390] Writing the router state
I0131 15:40:09.510855       1 router.go:395] Writing the router config
I0131 15:40:09.511325       1 router.go:211] matchPattern called with [1-9][0-9]*(us|ms|s|m|h|d)? and 
I0131 15:40:09.511463       1 router.go:214] matchPattern returning status: false
I0131 15:40:09.511503       1 router.go:211] matchPattern called with [1-9][0-9]*(us|ms|s|m|h|d)? and 
I0131 15:40:09.511571       1 router.go:214] matchPattern returning status: false
I0131 15:40:09.511603       1 router.go:211] matchPattern called with [1-9][0-9]*(us|ms|s|m|h|d)? and 
I0131 15:40:09.511720       1 router.go:214] matchPattern returning status: false
I0131 15:40:09.511752       1 router.go:211] matchPattern called with [1-9][0-9]*(us|ms|s|m|h|d)? and 
I0131 15:40:09.511812       1 router.go:214] matchPattern returning status: false
I0131 15:40:09.511835       1 router.go:211] matchPattern called with [1-9][0-9]*(us|ms|s|m|h|d)? and 
I0131 15:40:09.511896       1 router.go:214] matchPattern returning status: false
I0131 15:40:09.511916       1 router.go:211] matchPattern called with true|TRUE and false
I0131 15:40:09.511946       1 router.go:214] matchPattern returning status: false
I0131 15:40:09.512009       1 router.go:211] matchPattern called with true|TRUE and 
I0131 15:40:09.512033       1 router.go:214] matchPattern returning status: false
I0131 15:40:09.512055       1 router.go:211] matchPattern called with true|TRUE and 
I0131 15:40:09.512077       1 router.go:214] matchPattern returning status: false
I0131 15:40:09.512178       1 router.go:211] matchPattern called with roundrobin|leastconn|source and 
I0131 15:40:09.512219       1 router.go:214] matchPattern returning status: false
I0131 15:40:09.512242       1 router.go:211] matchPattern called with true|TRUE and 
I0131 15:40:09.512267       1 router.go:214] matchPattern returning status: false
I0131 15:40:09.512281       1 router.go:211] matchPattern called with true|TRUE and 
I0131 15:40:09.512307       1 router.go:214] matchPattern returning status: false
I0131 15:40:09.512938       1 router.go:211] matchPattern called with true|TRUE and 
I0131 15:40:09.512984       1 router.go:214] matchPattern returning status: false
I0131 15:40:09.513430       1 router.go:400] Reloading the router
I0131 15:40:09.550260       1 router.go:475] Router reloaded:
 - Checking HAProxy /healthz on port 1936 ...
 - HAProxy port 1936 health check ok : 0 retry attempt(s).
I0131 15:40:09.550282       1 reaper.go:24] Signal received: child exited
I0131 15:40:09.588276       1 reflector.go:234] Listing and watching *api.Endpoints from github.com/openshift/origin/pkg/router/controller/factory/factory.go:75
I0131 15:40:18.488177       1 reaper.go:24] Signal received: child exited
I0131 15:40:18.488224       1 reaper.go:32] Reaped process with pid 79
I0131 15:40:18.588907       1 reaper.go:24] Signal received: child exited
I0131 15:40:18.588951       1 reaper.go:32] Reaped process with pid 103
I0131 15:40:21.870456       1 reaper.go:24] Signal received: child exited
I0131 15:40:21.870497       1 reaper.go:32] Reaped process with pid 54
I0131 10:40:39.299063   28652 router_http_server.go:258] Stopping listener at 172.18.4.205:8080
I0131 10:40:39.299093   28652 router_http_server.go:258] Stopping listener at 172.18.4.205:8888
I0131 10:40:39.299101   28652 router_http_server.go:258] Stopping listener at 172.18.4.205:8889
I0131 10:40:39.299108   28652 router_http_server.go:258] Stopping listener at 172.18.4.205:8443
--- FAIL: TestRouter (33.46s)
	router_test.go:355: TC non-secure: url 0.0.0.0 alias www.example-unsecure.com protocol http
	router_test.go:355: TC non-secure-path: url 0.0.0.0/test alias www.example-unsecure.com protocol http
	router_test.go:355: TC preferred-port: url 0.0.0.0 alias www.example-unsecure.com protocol http
	router_test.go:355: TC edge termination: url 0.0.0.0 alias www.example.com protocol https
	router_test.go:355: TC edge termination path: url 0.0.0.0/test alias www.example.com protocol https
	router_test.go:355: TC reencrypt: url 0.0.0.0 alias www.example.com protocol https
	router_test.go:355: TC reencrypt-InsecureEdgePolicy: url 0.0.0.0 alias www.example.com protocol http
	router_test.go:357: TC reencrypt-InsecureEdgePolicy failed: unavailable the entire time: endpoint not available
FAIL
@stevekuznetsov stevekuznetsov added component/routing kind/test-flake Categorizes issue or PR as related to test flakes. priority/P1 labels Jan 31, 2017
@stevekuznetsov stevekuznetsov mentioned this issue Jan 31, 2017
Merged
@knobunc knobunc assigned ramr and unassigned knobunc Feb 2, 2017
ramr added a commit to ramr/origin that referenced this issue Feb 2, 2017
@ramr
Use watch.Deleted event on the endpoints to ensure we do a valid tran…
0ed96c6 
…sition

Deleted -> Added instead of Modified -> Added.
Otherwise the event queue code panics and kills the cache reflector
goroutine which causes events to never be delivered to the test router process.
fixes openshift#12736
@ramr ramr mentioned this issue Feb 2, 2017
Merged
This was referenced Feb 3, 2017
Merged
Merged
@knobunc knobunc reopened this Feb 3, 2017
@knobunc
Copy link
Contributor

knobunc commented Feb 3, 2017

We hit this again after the fix had merged.

@smarterclayton
Copy link
Contributor

I wonder if this is the same thing as #12784

@smarterclayton
Copy link
Contributor

An error inside the router that causes it to lose events

@ramr
Copy link
Contributor

ramr commented Feb 6, 2017

The error in #12784 error 7 means the curl couldn't connect - either the router pod is not yet up (or has been killed) or there was some network issue or then the router isn't binding to 80/443 because it hasn't done the initial sync.

This test is actually failing on the 7th or 8th route. I did notice that there was a copy paste on the routes in the test - will submit a fix for that - didn't think it should matter but it is off. The original error here was for the event queue transition (its hidden in the Full output under the fold: in the initial description above).

As re: the other issue #12784, events might not be the issue ... will post on that issue separately.

@ramr ramr mentioned this issue Feb 10, 2017
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@ramr ramr

Labels
component/routing kind/test-flake Categorizes issue or PR as related to test flakes. priority/P1
Projects
None yet
Milestone
No milestone
4 participants
@ramr @smarterclayton @stevekuznetsov @knobunc