Flaky Test: Test/ObservabilityFailureMode/allow_on_processor_error
P1Type: Bug
```
--- FAIL: Test (10.91s)
--- FAIL: Test/ObservabilityFailureMode (10.01s)
tlogger.go:133: INFO server.go:734 [core] [Server #1241] Server created (t=+239.104µs)
tlogger.go:133: INFO server.go:930 [core] [Server #1241 ListenSocket #1242] ListenSocket created (t=+321.367µs)
tlogger.go:133: INFO server.go:734 [core] [Server #1243] Server created (t=+373.543µs)
tlogger.go:133: INFO server.go:930 [core] [Server #1243 ListenSocket #1244] ListenSocket created (t=+488.815µs)
tlogger.go:133: INFO server.go:734 [core] [Server #1245] Server created (t=+507.232µs)
tlogger.go:133: INFO clientconn.go:1823 [core] original dial target is: "xds:///test-service" (t=+1.044939ms)
tlogger.go:133: INFO clientconn.go:514 [core] [Channel #1246] Channel created for target "xds:///test-service" (t=+1.059981ms)
tlogger.go:133: INFO clientconn.go:245 [core] [Channel #1246] parsed dial target is: resolver.Target{URL:url.URL{Scheme:"xds", Opaque:"", User:(*url.Userinfo)(nil), Host:"", Path:"/test-service", RawPath:"", OmitHost:false, ForceQuery:false, RawQuery:"", Fragment:"", RawFragment:""}} (t=+1.074112ms)
tlogger.go:133: INFO clientconn.go:246 [core] [Channel #1246] Channel authority set to "test-service" (t=+1.080071ms)
tlogger.go:133: INFO clientconn.go:619 [core] [Channel #1246] Channel Connectivity change to CONNECTING (t=+1.10008ms)
tlogger.go:133: INFO server.go:930 [core] [Server #1245 ListenSocket #1247] ListenSocket created (t=+1.127391ms)
tlogger.go:133: INFO pool.go:309 [xds] xDS node ID: 5815eb6b-604c-4563-bdbe-dadd6c19362f (t=+1.278665ms)
tlogger.go:133: INFO xds_resolver.go:160 [xds] [xds-resolver 0xc0006f8000] Creating resolver for target: xds:///test-service (t=+1.293617ms)
tlogger.go:133: INFO clientconn.go:1823 [core] original dial target is: "passthrough:///127.0.0.1:37351" (t=+1.324302ms)
tlogger.go:133: INFO clientconn.go:514 [core] [Channel #1248] Channel created for target "passthrough:///127.0.0.1:37351" (t=+1.352204ms)
tlogger.go:133: INFO clientconn.go:245 [core] [Channel #1248] parsed dial target is: resolver.Target{URL:url.URL{Scheme:"passthrough", Opaque:"", User:(*url.Userinfo)(nil), Host:"", Path:"/127.0.0.1:37351", RawPath:"", OmitHost:false, ForceQuery:false, RawQuery:"", Fragment:"", RawFragment:""}} (t=+1.36315ms)
tlogger.go:133: INFO clientconn.go:246 [core] [Channel #1248] Channel authority set to "127.0.0.1:37351" (t=+1.371342ms)
tlogger.go:133: INFO clientconn.go:419 [core] [Channel #1246] Channel exiting idle mode (t=+1.39686ms)
tlogger.go:133: INFO clientconn.go:619 [core] [Channel #1248] Channel Connectivity change to CONNECTING (t=+1.425172ms)
tlogger.go:133: INFO balancer_wrapper.go:121 [core] [Channel #1248] Channel switches to new LB policy "pick_first" (t=+1.442157ms)
tlogger.go:133: INFO clientconn.go:922 [core] [Channel #1248 SubChannel #1249] Subchannel created (t=+1.475006ms)
tlogger.go:133: INFO clientconn.go:419 [core] [Channel #1248] Channel exiting idle mode (t=+1.485812ms)
tlogger.go:133: INFO clientconn.go:1302 [core] [Channel #1248 SubChannel #1249] Subchannel Connectivity change to CONNECTING (t=+1.51185ms)
tlogger.go:133: INFO clientconn.go:1470 [core] [Channel #1248 SubChannel #1249] Subchannel picks a new address "127.0.0.1:37351" to connect (t=+1.520183ms)
tlogger.go:133: INFO clientconn.go:1302 [core] [Channel #1248 SubChannel #1249] Subchannel Connectivity change to READY (t=+1.759397ms)
tlogger.go:133: INFO clientconn.go:619 [core] [Channel #1248] Channel Connectivity change to READY (t=+1.785396ms)
tlogger.go:133: INFO clientconn.go:1823 [core] original dial target is: "127.0.0.1:39097" (t=+2.613893ms)
tlogger.go:133: INFO clientconn.go:514 [core] [Channel #1252] Channel created for target "127.0.0.1:39097" (t=+2.631208ms)
tlogger.go:133: INFO clientconn.go:245 [core] [Channel #1252] parsed dial target is: resolver.Target{URL:url.URL{Scheme:"dns", Opaque:"", User:(*url.Userinfo)(nil), Host:"", Path:"/127.0.0.1:39097", RawPath:"", OmitHost:false, ForceQuery:false, RawQuery:"", Fragment:"", RawFragment:""}} (t=+2.648224ms)
tlogger.go:133: INFO clientconn.go:246 [core] [Channel #1252] Channel authority set to "127.0.0.1:39097" (t=+2.663857ms)
tlogger.go:133: INFO balancer_wrapper.go:121 [core] [Channel #1246] Channel switches to new LB policy "xds_cluster_manager_experimental" (t=+2.762303ms)
tlogger.go:133: INFO clustermanager.go:58 [xds] [xds-cluster-manager-lb 0xc000724940] Created (t=+2.783204ms)
tlogger.go:133: INFO balancergroup.go:274 [xds] [xds-cluster-manager-lb 0xc000724940] Adding child policy of type "cds_experimental" for child "cluster:cluster-test-service" (t=+2.795151ms)
tlogger.go:133: INFO balancergroup.go:102 [xds] [xds-cluster-manager-lb 0xc000724940] Creating child policy of type "cds_experimental" for child "cluster:cluster-test-service" (t=+2.802212ms)
tlogger.go:133: INFO cdsbalancer.go:90 [xds] [cds-lb 0xc0006f6380] Created (t=+2.811946ms)
tlogger.go:133: INFO cdsbalancer.go:167 [xds] [cds-lb 0xc0006f6380] Received balancer config update: {
"LoadBalancingConfig": null,
"cluster": "cluster-test-service",
"isDynamic": false
} (t=+2.825566ms)
tlogger.go:133: INFO balancer.go:76 [xds] [priority-lb 0xc000282310] Created (t=+2.866457ms)
tlogger.go:133: INFO balancergroup.go:528 [xds] [xds-cluster-manager-lb 0xc000724940] Balancer state update from child cluster:cluster-test-service, new state: {ConnectivityState:CONNECTING Picker:0xc0006bfb50} (t=+2.970671ms)
tlogger.go:133: INFO balancerstateaggregator.go:147 [xds] [xds-cluster-manager-lb 0xc000724940] State update from sub-balancer "cluster:cluster-test-service": {ConnectivityState:CONNECTING Picker:0xc0006bfb50} (t=+2.980947ms)
tlogger.go:133: INFO balancergroup.go:274 [xds] [priority-lb 0xc000282310] Adding child policy of type "outlier_detection_experimental" for child "priority-0-0" (t=+2.993315ms)
tlogger.go:133: INFO balancergroup.go:102 [xds] [priority-lb 0xc000282310] Creating child policy of type "outlier_detection_experimental" for child "priority-0-0" (t=+3.000005ms)
tlogger.go:133: INFO balancer.go:94 [xds] [outlier-detection-lb 0xc00016d590] Created (t=+3.009549ms)
tlogger.go:133: INFO clusterimpl.go:89 [xds] [xds-cluster-impl-lb 0xc00061b320] Created (t=+3.028287ms)
tlogger.go:133: INFO clusterimpl.go:101 [xds] [xds-cluster-impl-lb 0xc00061b320] xDS credentials in use: false (t=+3.038963ms)
tlogger.go:133: INFO weightedtarget.go:65 [xds] [weighted-target-lb 0xc000724e60] Created (t=+3.072312ms)
tlogger.go:133: INFO balancer.go:88 [xds] [wrrlocality-lb 0xc00064f560] Created (t=+3.087154ms)
tlogger.go:133: INFO balancergroup.go:274 [xds] [weighted-target-lb 0xc000724e60] Adding child policy of type "round_robin" for child "{region=\"region-1\", zone=\"zone-1\", sub_zone=\"subzone-1\"}" (t=+3.111901ms)
tlogger.go:133: INFO balancergroup.go:102 [xds] [weighted-target-lb 0xc000724e60] Creating child policy of type "round_robin" for child "{region=\"region-1\", zone=\"zone-1\", sub_zone=\"subzone-1\"}" (t=+3.122636ms)
tlogger.go:133: INFO roundrobin.go:56 [roundrobin] [0xc00064f890] Created (t=+3.132301ms)
tlogger.go:133: INFO clientconn.go:922 [core] [Channel #1246 SubChannel #1253] Subchannel created (t=+3.156567ms)
tlogger.go:133: INFO balancergroup.go:528 [xds] [weighted-target-lb 0xc000724e60] Balancer state update from child {region="region-1", zone="zone-1", sub_zone="subzone-1"}, new state: {ConnectivityState:CONNECTING Picker:0xc0006ae900} (t=+3.179831ms)
tlogger.go:133: INFO aggregator.go:253 [xds] [weighted-target-lb 0xc000724e60] Child pickers with config: map[{region="region-1", zone="zone-1", sub_zone="subzone-1"}:weight:1,picker:0xc0006ae900,state:CONNECTING,stateToAggregate:CONNECTING] (t=+3.19277ms)
tlogger.go:133: INFO balancergroup.go:528 [xds] [priority-lb 0xc000282310] Balancer state update from child priority-0-0, new state: {ConnectivityState:CONNECTING Picker:0xc000546d38} (t=+3.208444ms)
tlogger.go:133: INFO balancergroup.go:528 [xds] [xds-cluster-manager-lb 0xc000724940] Balancer state update from child cluster:cluster-test-service, new state: {ConnectivityState:CONNECTING Picker:0xc000546d38} (t=+3.216075ms)
tlogger.go:133: INFO balancerstateaggregator.go:147 [xds] [xds-cluster-manager-lb 0xc000724940] State update from sub-balancer "cluster:cluster-test-service": {ConnectivityState:CONNECTING Picker:0xc000546d38} (t=+3.221723ms)
tlogger.go:133: INFO balancerstateaggregator.go:191 [xds] [xds-cluster-manager-lb 0xc000724940] Child pickers: map[cluster:cluster-test-service:picker:0xc000546d38,state:CONNECTING,stateToAggregate:CONNECTING] (t=+3.230006ms)
tlogger.go:133: INFO clientconn.go:619 [core] [Channel #1252] Channel Connectivity change to CONNECTING (t=+3.244677ms)
tlogger.go:133: INFO balancer_wrapper.go:121 [core] [Channel #1252] Channel switches to new LB policy "pick_first" (t=+3.271267ms)
tlogger.go:133: INFO clientconn.go:1302 [core] [Channel #1246 SubChannel #1253] Subchannel Connectivity change to CONNECTING (t=+3.281082ms)
tlogger.go:133: INFO clientconn.go:1470 [core] [Channel #1246 SubChannel #1253] Subchannel picks a new address "localhost:46567" to connect (t=+3.303325ms)
tlogger.go:133: INFO clientconn.go:922 [core] [Channel #1252 SubChannel #1254] Subchannel created (t=+3.355261ms)
tlogger.go:133: INFO clientconn.go:419 [core] [Channel #1252] Channel exiting idle mode (t=+3.607205ms)
tlogger.go:133: INFO clientconn.go:1302 [core] [Channel #1252 SubChannel #1254] Subchannel Connectivity change to CONNECTING (t=+3.649898ms)
tlogger.go:133: INFO clientconn.go:1470 [core] [Channel #1252 SubChannel #1254] Subchannel picks a new address "127.0.0.1:39097" to connect (t=+3.663368ms)
tlogger.go:133: INFO clientconn.go:1302 [core] [Channel #1246 SubChannel #1253] Subchannel Connectivity change to READY (t=+4.080236ms)
tlogger.go:133: INFO balancergroup.go:528 [xds] [weighted-target-lb 0xc000724e60] Balancer state update from child {region="region-1", zone="zone-1", sub_zone="subzone-1"}, new state: {ConnectivityState:READY Picker:0xc0006aed00} (t=+4.126514ms)
tlogger.go:133: INFO aggregator.go:253 [xds] [weighted-target-lb 0xc000724e60] Child pickers with config: map[{region="region-1", zone="zone-1", sub_zone="subzone-1"}:weight:1,picker:0xc0006aed00,state:READY,stateToAggregate:READY] (t=+4.149038ms)
tlogger.go:133: INFO balancergroup.go:528 [xds] [priority-lb 0xc000282310] Balancer state update from child priority-0-0, new state: {ConnectivityState:READY Picker:0xc000546e58} (t=+4.168897ms)
tlogger.go:133: INFO balancergroup.go:528 [xds] [xds-cluster-manager-lb 0xc000724940] Balancer state update from child cluster:cluster-test-service, new state: {ConnectivityState:READY Picker:0xc000546e58} (t=+4.185101ms)
tlogger.go:133: INFO balancerstateaggregator.go:147 [xds] [xds-cluster-manager-lb 0xc000724940] State update from sub-balancer "cluster:cluster-test-service": {ConnectivityState:READY Picker:0xc000546e58} (t=+4.19766ms)
tlogger.go:133: INFO balancerstateaggregator.go:191 [xds] [xds-cluster-manager-lb 0xc000724940] Child pickers: map[cluster:cluster-test-service:picker:0xc000546e58,state:READY,stateToAggregate:READY] (t=+4.211821ms)
tlogger.go:133: INFO clientconn.go:619 [core] [Channel #1246] Channel Connectivity change to READY (t=+4.22494ms)
tlogger.go:133: INFO clientconn.go:1302 [core] [Channel #1252 SubChannel #1254] Subchannel Connectivity change to READY (t=+4.257488ms)
tlogger.go:133: INFO clientconn.go:619 [core] [Channel #1252] Channel Connectivity change to READY (t=+4.284398ms)
tlogger.go:133: INFO clientconn.go:619 [core] [Channel #1246] Channel Connectivity change to SHUTDOWN (t=+10.002359581s)
tlogger.go:133: INFO resolver_wrapper.go:112 [core] [Channel #1246] Closing the name resolver (t=+10.002381063s)
tlogger.go:133: INFO balancer_wrapper.go:159 [core] [Channel #1246] ccBalancerWrapper: closing (t=+10.002405008s)
tlogger.go:133: INFO clusterimpl.go:523 [xds] [xds-cluster-impl-lb 0xc00061b320] Shutdown (t=+10.002505958s)
tlogger.go:133: INFO balancergroup.go:351 [xds] [priority-lb 0xc000282310] Removing child policy for child "priority-0-0" (t=+10.002529162s)
tlogger.go:133: INFO cdsbalancer.go:416 [xds] [cds-lb 0xc0006f6380] Shutdown (t=+10.00254769s)
tlogger.go:133: INFO clustermanager.go:192 [xds] [xds-cluster-manager-lb 0xc000724940] Shutdown (t=+10.002559918s)
tlogger.go:129: WARNING ads_stream.go:410 [xds] [xds-client 0xc00081cf00] [xds-channel 0xc000649860] [ads-stream 0xc00081cfa0] Sending ADS request for type "type.googleapis.com/envoy.config.listener.v3.Listener", resources: [], version: "1", nonce: "1" failed: EOF (t=+10.002592226s)
tlogger.go:129: WARNING ads_stream.go:452 [xds] [xds-client 0xc00081cf00] [xds-channel 0xc000649860] [ads-stream 0xc00081cfa0] ADS stream closed: rpc error: code = Canceled desc = context canceled (t=+10.002617313s)
tlogger.go:133: INFO ads_stream.go:165 [xds] [xds-client 0xc00081cf00] [xds-channel 0xc000649860] [ads-stream 0xc00081cfa0] Shutdown ADS stream (t=+10.002631734s)
tlogger.go:133: INFO clientconn.go:619 [core] [Channel #1248] Channel Connectivity change to SHUTDOWN (t=+10.002662149s)
tlogger.go:133: INFO resolver_wrapper.go:112 [core] [Channel #1248] Closing the name resolver (t=+10.002674968s)
tlogger.go:133: INFO balancer_wrapper.go:159 [core] [Channel #1248] ccBalancerWrapper: closing (t=+10.002688909s)
tlogger.go:133: INFO clientconn.go:1302 [core] [Channel #1248 SubChannel #1249] Subchannel Connectivity change to SHUTDOWN (t=+10.002731982s)
tlogger.go:133: INFO clientconn.go:1696 [core] [Channel #1248 SubChannel #1249] Subchannel deleted (t=+10.00274355s)
tlogger.go:133: INFO clientconn.go:1231 [core] [Channel #1248] Channel deleted (t=+10.002850939s)
tlogger.go:133: INFO channel.go:143 [xds] [xds-client 0xc00081cf00] [xds-channel 0xc000649860] Shutdown (t=+10.002866902s)
tlogger.go:133: INFO xdsclient.go:210 [xds] [xds-client 0xc00081cf00] Shutdown (t=+10.002889215s)
tlogger.go:133: INFO clientconn.go:619 [core] [Channel #1252] Channel Connectivity change to SHUTDOWN (t=+10.002903917s)
tlogger.go:133: INFO resolver_wrapper.go:112 [core] [Channel #1252] Closing the name resolver (t=+10.002916756s)
tlogger.go:133: INFO balancer_wrapper.go:159 [core] [Channel #1252] ccBalancerWrapper: closing (t=+10.002928704s)
tlogger.go:133: INFO clientconn.go:1302 [core] [Channel #1252 SubChannel #1254] Subchannel Connectivity change to SHUTDOWN (t=+10.002962283s)
tlogger.go:133: INFO clientconn.go:1696 [core] [Channel #1252 SubChannel #1254] Subchannel deleted (t=+10.00297371s)
tlogger.go:133: INFO clientconn.go:1231 [core] [Channel #1252] Channel deleted (t=+10.003044766s)
tlogger.go:133: INFO xds_resolver.go:301 [xds] [xds-resolver 0xc0006f8000] Shutdown (t=+10.00306112s)
tlogger.go:133: INFO clientconn.go:1302 [core] [Channel #1246 SubChannel #1253] Subchannel Connectivity change to SHUTDOWN (t=+10.003082592s)
tlogger.go:133: INFO clientconn.go:1696 [core] [Channel #1246 SubChannel #1253] Subchannel deleted (t=+10.003093117s)
tlogger.go:133: INFO clientconn.go:1231 [core] [Channel #1246] Channel deleted (t=+10.003144984s)
tlogger.go:133: INFO server.go:866 [core] [Server #1243 ListenSocket #1244] ListenSocket deleted (t=+10.003188168s)
tlogger.go:133: INFO server.go:866 [core] [Server #1245 ListenSocket #1247] ListenSocket deleted (t=+10.003221377s)
tlogger.go:133: INFO server.go:866 [core] [Server #1241 ListenSocket #1242] ListenSocket deleted (t=+10.003248056s)
--- FAIL: Test/ObservabilityFailureMode/allow_on_processor_error (10.00s)
stubserver.go:300: Started test service backend at "127.0.0.1:46567"
setup.go:45: Created new snapshot cache...
setup.go:45: Registered Aggregated Discovery Service (ADS)...
setup.go:45: xDS management server serving at: 127.0.0.1:37351...
server.go:229: Created new resource snapshot...
logging.go:30: setting snapshot for node 5815eb6b-604c-4563-bdbe-dadd6c19362f
server.go:235: Updated snapshot cache with resource snapshot...
logging.go:30: respond type.googleapis.com/envoy.config.listener.v3.Listener (requested [test-service]) version "" with version "1" and resources [test-service]
logging.go:30: open watch 1 for type.googleapis.com/envoy.config.listener.v3.Listener map[test-service:{}] from nodeID "5815eb6b-604c-4563-bdbe-dadd6c19362f", version "1"
logging.go:30: respond type.googleapis.com/envoy.config.route.v3.RouteConfiguration (requested [route-test-service]) version "" with version "1" and resources [route-test-service]
logging.go:30: open watch 2 for type.googleapis.com/envoy.config.route.v3.RouteConfiguration map[route-test-service:{}] from nodeID "5815eb6b-604c-4563-bdbe-dadd6c19362f", version "1"
logging.go:30: respond type.googleapis.com/envoy.config.cluster.v3.Cluster (requested [cluster-test-service]) version "" with version "1" and resources [cluster-test-service]
logging.go:30: open watch 3 for type.googleapis.com/envoy.config.cluster.v3.Cluster map[cluster-test-service:{}] from nodeID "5815eb6b-604c-4563-bdbe-dadd6c19362f", version "1"
logging.go:30: respond type.googleapis.com/envoy.config.endpoint.v3.ClusterLoadAssignment (requested [endpoints-test-service]) version "" with version "1" and resources [endpoints-test-service]
logging.go:30: open watch 4 for type.googleapis.com/envoy.config.endpoint.v3.ClusterLoadAssignment map[endpoints-test-service:{}] from nodeID "5815eb6b-604c-4563-bdbe-dadd6c19362f", version "1"
ext_proc_ext_test.go:3850: UnaryCall() status code = DeadlineExceeded, want OK
tlogger.go:133: INFO server.go:734 [core] [Server #1259] Server created (t=+10.003577474s)
tlogger.go:133: INFO server.go:734 [core] [Server #1260] Server created (t=+10.003679786s)
tlogger.go:133: INFO server.go:734 [core] [Server #1261] Server created (t=+10.00379111s)
tlogger.go:133: INFO server.go:930 [core] [Server #1260 ListenSocket #1263] ListenSocket created (t=+10.004307475s)
tlogger.go:133: INFO server.go:930 [core] [Server #1259 ListenSocket #1262] ListenSocket created (t=+10.004339512s)
tlogger.go:133: INFO server.go:930 [core] [Server #1261 ListenSocket #1264] ListenSocket created (t=+10.004428464s)
tlogger.go:133: INFO clientconn.go:1823 [core] original dial target is: "xds:///test-service" (t=+10.004627549s)
tlogger.go:133: INFO clientconn.go:514 [core] [Channel #1265] Channel created for target "xds:///test-service" (t=+10.004646226s)
tlogger.go:133: INFO clientconn.go:245 [core] [Channel #1265] parsed dial target is: resolver.Target{URL:url.URL{Scheme:"xds", Opaque:"", User:(*url.Userinfo)(nil), Host:"", Path:"/test-service", RawPath:"", OmitHost:false, ForceQuery:false, RawQuery:"", Fragment:"", RawFragment:""}} (t=+10.004666546s)
tlogger.go:133: INFO clientconn.go:246 [core] [Channel #1265] Channel authority set to "test-service" (t=+10.004676421s)
tlogger.go:133: INFO clientconn.go:619 [core] [Channel #1265] Channel Connectivity change to CONNECTING (t=+10.004712695s)
tlogger.go:133: INFO pool.go:309 [xds] xDS node ID: c752e9f6-decf-46ab-bc10-621c611bb6ff (t=+10.004881885s)
tlogger.go:133: INFO xds_resolver.go:160 [xds] [xds-resolver 0xc0006f80b0] Creating resolver for target: xds:///test-service (t=+10.004901955s)
tlogger.go:133: INFO clientconn.go:1823 [core] original dial target is: "passthrough:///127.0.0.1:38955" (t=+10.004946881s)
tlogger.go:133: INFO clientconn.go:514 [core] [Channel #1266] Channel created for target "passthrough:///127.0.0.1:38955" (t=+10.004972379s)
tlogger.go:133: INFO clientconn.go:245 [core] [Channel #1266] parsed dial target is: resolver.Target{URL:url.URL{Scheme:"passthrough", Opaque:"", User:(*url.Userinfo)(nil), Host:"", Path:"/127.0.0.1:38955", RawPath:"", OmitHost:false, ForceQuery:false, RawQuery:"", Fragment:"", RawFragment:""}} (t=+10.004987501s)
tlogger.go:133: INFO clientconn.go:246 [core] [Channel #1266] Channel authority set to "127.0.0.1:38955" (t=+10.004999009s)
tlogger.go:133: INFO clientconn.go:419 [core] [Channel #1265] Channel exiting idle mode (t=+10.00503401s)
tlogger.go:133: INFO clientconn.go:619 [core] [Channel #1266] Channel Connectivity change to CONNECTING (t=+10.00506767s)
tlogger.go:133: INFO balancer_wrapper.go:121 [core] [Channel #1266] Channel switches to new LB policy "pick_first" (t=+10.005091205s)
tlogger.go:133: INFO clientconn.go:922 [core] [Channel #1266 SubChannel #1267] Subchannel created (t=+10.005128741s)
tlogger.go:133: INFO clientconn.go:419 [core] [Channel #1266] Channel exiting idle mode (t=+10.005147408s)
tlogger.go:133: INFO clientconn.go:1302 [core] [Channel #1266 SubChannel #1267] Subchannel Connectivity change to CONNECTING (t=+10.005179406s)
tlogger.go:133: INFO clientconn.go:1470 [core] [Channel #1266 SubChannel #1267] Subchannel picks a new address "127.0.0.1:38955" to connect (t=+10.005191944s)
tlogger.go:133: INFO clientconn.go:1302 [core] [Channel #1266 SubChannel #1267] Subchannel Connectivity change to READY (t=+10.005451879s)
tlogger.go:133: INFO clientconn.go:619 [core] [Channel #1266] Channel Connectivity change to READY (t=+10.005476345s)
tlogger.go:133: INFO clientconn.go:1823 [core] original dial target is: "127.0.0.1:43855" (t=+10.006836959s)
tlogger.go:133: INFO clientconn.go:514 [core] [Channel #1270] Channel created for target "127.0.0.1:43855" (t=+10.006875296s)
tlogger.go:133: INFO clientconn.go:245 [core] [Channel #1270] parsed dial target is: resolver.Target{URL:url.URL{Scheme:"dns", Opaque:"", User:(*url.Userinfo)(nil), Host:"", Path:"/127.0.0.1:43855", RawPath:"", OmitHost:false, ForceQuery:false, RawQuery:"", Fragment:"", RawFragment:""}} (t=+10.00689169s)
tlogger.go:133: INFO clientconn.go:246 [core] [Channel #1270] Channel authority set to "127.0.0.1:43855" (t=+10.006905351s)
tlogger.go:133: INFO balancer_wrapper.go:121 [core] [Channel #1265] Channel switches to new LB policy "xds_cluster_manager_experimental" (t=+10.006989125s)
tlogger.go:133: INFO clustermanager.go:58 [xds] [xds-cluster-manager-lb 0xc000530ee0] Created (t=+10.007010506s)
tlogger.go:133: INFO balancergroup.go:274 [xds] [xds-cluster-manager-lb 0xc000530ee0] Adding child policy of type "cds_experimental" for child "cluster:cluster-test-service" (t=+10.007024066s)
tlogger.go:133: INFO balancergroup.go:102 [xds] [xds-cluster-manager-lb 0xc000530ee0] Creating child policy of type "cds_experimental" for child "cluster:cluster-test-service" (t=+10.007035293s)
tlogger.go:133: INFO cdsbalancer.go:90 [xds] [cds-lb 0xc000a18540] Created (t=+10.007048983s)
tlogger.go:133: INFO cdsbalancer.go:167 [xds] [cds-lb 0xc000a18540] Received balancer config update: {
"LoadBalancingConfig": null,
"cluster": "cluster-test-service",
"isDynamic": false
} (t=+10.00706729s)
tlogger.go:133: INFO balancer.go:76 [xds] [priority-lb 0xc0002b08c0] Created (t=+10.007116373s)
tlogger.go:133: INFO balancergroup.go:528 [xds] [xds-cluster-manager-lb 0xc000530ee0] Balancer state update from child cluster:cluster-test-service, new state: {ConnectivityState:CONNECTING Picker:0xc0005cd2d0} (t=+10.007261117s)
tlogger.go:133: INFO balancerstateaggregator.go:147 [xds] [xds-cluster-manager-lb 0xc000530ee0] State update from sub-balancer "cluster:cluster-test-service": {ConnectivityState:CONNECTING Picker:0xc0005cd2d0} (t=+10.007273375s)
tlogger.go:133: INFO balancergroup.go:274 [xds] [priority-lb 0xc0002b08c0] Adding child policy of type "outlier_detection_experimental" for child "priority-0-0" (t=+10.007291963s)
tlogger.go:133: INFO balancergroup.go:102 [xds] [priority-lb 0xc0002b08c0] Creating child policy of type "outlier_detection_experimental" for child "priority-0-0" (t=+10.007305583s)
tlogger.go:133: INFO balancer.go:94 [xds] [outlier-detection-lb 0xc0006e8690] Created (t=+10.007319484s)
tlogger.go:133: INFO clusterimpl.go:89 [xds] [xds-cluster-impl-lb 0xc00055b560] Created (t=+10.007409327s)
tlogger.go:133: INFO clusterimpl.go:101 [xds] [xds-cluster-impl-lb 0xc00055b560] xDS credentials in use: false (t=+10.007424319s)
tlogger.go:133: INFO weightedtarget.go:65 [xds] [weighted-target-lb 0xc000531720] Created (t=+10.007519089s)
tlogger.go:133: INFO balancer.go:88 [xds] [wrrlocality-lb 0xc0005b6510] Created (t=+10.007533921s)
tlogger.go:133: INFO balancergroup.go:274 [xds] [weighted-target-lb 0xc000531720] Adding child policy of type "round_robin" for child "{region=\"region-1\", zone=\"zone-1\", sub_zone=\"subzone-1\"}" (t=+10.007563275s)
tlogger.go:133: INFO balancergroup.go:102 [xds] [weighted-target-lb 0xc000531720] Creating child policy of type "round_robin" for child "{region=\"region-1\", zone=\"zone-1\", sub_zone=\"subzone-1\"}" (t=+10.007576955s)
tlogger.go:133: INFO roundrobin.go:56 [roundrobin] [0xc0005b6c00] Created (t=+10.007591917s)
tlogger.go:133: INFO clientconn.go:922 [core] [Channel #1265 SubChannel #1271] Subchannel created (t=+10.00762794s)
tlogger.go:133: INFO balancergroup.go:528 [xds] [weighted-target-lb 0xc000531720] Balancer state update from child {region="region-1", zone="zone-1", sub_zone="subzone-1"}, new state: {ConnectivityState:CONNECTING Picker:0xc000660800} (t=+10.007663873s)
tlogger.go:133: INFO aggregator.go:253 [xds] [weighted-target-lb 0xc000531720] Child pickers with config: map[{region="region-1", zone="zone-1", sub_zone="subzone-1"}:weight:1,picker:0xc000660800,state:CONNECTING,stateToAggregate:CONNECTING] (t=+10.007683613s)
tlogger.go:133: INFO clientconn.go:1302 [core] [Channel #1265 SubChannel #1271] Subchannel Connectivity change to CONNECTING (t=+10.007718654s)
tlogger.go:133: INFO clientconn.go:1470 [core] [Channel #1265 SubChannel #1271] Subchannel picks a new address "localhost:35195" to connect (t=+10.007732415s)
tlogger.go:133: INFO balancergroup.go:528 [xds] [priority-lb 0xc0002b08c0] Balancer state update from child priority-0-0, new state: {ConnectivityState:CONNECTING Picker:0xc00017edb0} (t=+10.007803931s)
tlogger.go:133: INFO balancergroup.go:528 [xds] [xds-cluster-manager-lb 0xc000530ee0] Balancer state update from child cluster:cluster-test-service, new state: {ConnectivityState:CONNECTING Picker:0xc00017edb0} (t=+10.007871501s)
tlogger.go:133: INFO balancerstateaggregator.go:147 [xds] [xds-cluster-manager-lb 0xc000530ee0] State update from sub-balancer "cluster:cluster-test-service": {ConnectivityState:CONNECTING Picker:0xc00017edb0} (t=+10.007893103s)
tlogger.go:133: INFO balancerstateaggregator.go:191 [xds] [xds-cluster-manager-lb 0xc000530ee0] Child pickers: map[cluster:cluster-test-service:picker:0xc0005cd2d0,state:CONNECTING,stateToAggregate:CONNECTING] (t=+10.00822914s)
tlogger.go:133: INFO clientconn.go:619 [core] [Channel #1270] Channel Connectivity change to CONNECTING (t=+10.008256421s)
tlogger.go:133: INFO clientconn.go:1302 [core] [Channel #1265 SubChannel #1271] Subchannel Connectivity change to READY (t=+10.008325032s)
tlogger.go:133: INFO balancerstateaggregator.go:191 [xds] [xds-cluster-manager-lb 0xc000530ee0] Child pickers: map[cluster:cluster-test-service:picker:0xc00017edb0,state:CONNECTING,stateToAggregate:CONNECTING] (t=+10.008398831s)
tlogger.go:133: INFO balancer_wrapper.go:121 [core] [Channel #1270] Channel switches to new LB policy "pick_first" (t=+10.008430979s)
tlogger.go:133: INFO clientconn.go:922 [core] [Channel #1270 SubChannel #1274] Subchannel created (t=+10.008461484s)
tlogger.go:133: INFO clientconn.go:419 [core] [Channel #1270] Channel exiting idle mode (t=+10.008476967s)
tlogger.go:133: INFO balancergroup.go:528 [xds] [weighted-target-lb 0xc000531720] Balancer state update from child {region="region-1", zone="zone-1", sub_zone="subzone-1"}, new state: {ConnectivityState:READY Picker:0xc000842240} (t=+10.008494794s)
tlogger.go:133: INFO aggregator.go:253 [xds] [weighted-target-lb 0xc000531720] Child pickers with config: map[{region="region-1", zone="zone-1", sub_zone="subzone-1"}:weight:1,picker:0xc000842240,state:READY,stateToAggregate:READY] (t=+10.008509836s)
tlogger.go:133: INFO balancergroup.go:528 [xds] [priority-lb 0xc0002b08c0] Balancer state update from child priority-0-0, new state: {ConnectivityState:READY Picker:0xc0005466f0} (t=+10.008551598s)
tlogger.go:133: INFO balancergroup.go:528 [xds] [xds-cluster-manager-lb 0xc000530ee0] Balancer state update from child cluster:cluster-test-service, new state: {ConnectivityState:READY Picker:0xc0005466f0} (t=+10.008564066s)
tlogger.go:133: INFO balancerstateaggregator.go:147 [xds] [xds-cluster-manager-lb 0xc000530ee0] State update from sub-balancer "cluster:cluster-test-service": {ConnectivityState:READY Picker:0xc0005466f0} (t=+10.008574472s)
tlogger.go:133: INFO balancerstateaggregator.go:191 [xds] [xds-cluster-manager-lb 0xc000530ee0] Child pickers: map[cluster:cluster-test-service:picker:0xc0005466f0,state:READY,stateToAggregate:READY] (t=+10.008585047s)
tlogger.go:133: INFO clientconn.go:619 [core] [Channel #1265] Channel Connectivity change to READY (t=+10.008596835s)
tlogger.go:133: INFO clientconn.go:1302 [core] [Channel #1270 SubChannel #1274] Subchannel Connectivity change to CONNECTING (t=+10.00860752s)
tlogger.go:133: INFO clientconn.go:1470 [core] [Channel #1270 SubChannel #1274] Subchannel picks a new address "127.0.0.1:43855" to connect (t=+10.008619268s)
tlogger.go:133: INFO clientconn.go:1302 [core] [Channel #1270 SubChannel #1274] Subchannel Connectivity change to READY (t=+10.008819233s)
tlogger.go:133: INFO clientconn.go:619 [core] [Channel #1270] Channel Connectivity change to READY (t=+10.008870299s)
tlogger.go:133: INFO clientconn.go:619 [core] [Channel #1265] Channel Connectivity change to SHUTDOWN (t=+10.009184274s)
tlogger.go:133: INFO resolver_wrapper.go:112 [core] [Channel #1265] Closing the name resolver (t=+10.009197364s)
tlogger.go:133: INFO balancer_wrapper.go:159 [core] [Channel #1265] ccBalancerWrapper: closing (t=+10.009209241s)
tlogger.go:133: INFO clusterimpl.go:523 [xds] [xds-cluster-impl-lb 0xc00055b560] Shutdown (t=+10.009262891s)
tlogger.go:133: INFO balancergroup.go:351 [xds] [priority-lb 0xc0002b08c0] Removing child policy for child "priority-0-0" (t=+10.009279185s)
tlogger.go:133: INFO cdsbalancer.go:416 [xds] [cds-lb 0xc000a18540] Shutdown (t=+10.009289941s)
tlogger.go:133: INFO clustermanager.go:192 [xds] [xds-cluster-manager-lb 0xc000530ee0] Shutdown (t=+10.009299004s)
tlogger.go:129: WARNING ads_stream.go:410 [xds] [xds-client 0xc00081c1e0] [xds-channel 0xc0007bfb80] [ads-stream 0xc00081c280] Sending ADS request for type "type.googleapis.com/envoy.config.listener.v3.Listener", resources: [], version: "1", nonce: "1" failed: EOF (t=+10.00931624s)
tlogger.go:129: WARNING ads_stream.go:452 [xds] [xds-client 0xc00081c1e0] [xds-channel 0xc0007bfb80] [ads-stream 0xc00081c280] ADS stream closed: rpc error: code = Canceled desc = context canceled (t=+10.009396468s)
tlogger.go:133: INFO ads_stream.go:165 [xds] [xds-client 0xc00081c1e0] [xds-channel 0xc0007bfb80] [ads-stream 0xc00081c280] Shutdown ADS stream (t=+10.009442146s)
tlogger.go:133: INFO clientconn.go:619 [core] [Channel #1266] Channel Connectivity change to SHUTDOWN (t=+10.009455846s)
tlogger.go:133: INFO resolver_wrapper.go:112 [core] [Channel #1266] Closing the name resolver (t=+10.009467323s)
tlogger.go:133: INFO balancer_wrapper.go:159 [core] [Channel #1266] ccBalancerWrapper: closing (t=+10.009480513s)
tlogger.go:133: INFO clientconn.go:1302 [core] [Channel #1266 SubChannel #1267] Subchannel Connectivity change to SHUTDOWN (t=+10.009517668s)
tlogger.go:133: INFO clientconn.go:1696 [core] [Channel #1266 SubChannel #1267] Subchannel deleted (t=+10.00953285s)
tlogger.go:133: INFO clientconn.go:1231 [core] [Channel #1266] Channel deleted (t=+10.009596875s)
tlogger.go:133: INFO channel.go:143 [xds] [xds-client 0xc00081c1e0] [xds-channel 0xc0007bfb80] Shutdown (t=+10.009610906s)
tlogger.go:133: INFO xdsclient.go:210 [xds] [xds-client 0xc00081c1e0] Shutdown (t=+10.009628902s)
tlogger.go:133: INFO clientconn.go:619 [core] [Channel #1270] Channel Connectivity change to SHUTDOWN (t=+10.009641431s)
tlogger.go:133: INFO resolver_wrapper.go:112 [core] [Channel #1270] Closing the name resolver (t=+10.009652337s)
tlogger.go:133: INFO balancer_wrapper.go:159 [core] [Channel #1270] ccBalancerWrapper: closing (t=+10.009664846s)
tlogger.go:133: INFO clientconn.go:1302 [core] [Channel #1270 SubChannel #1274] Subchannel Connectivity change to SHUTDOWN (t=+10.009690494s)
tlogger.go:133: INFO clientconn.go:1696 [core] [Channel #1270 SubChannel #1274] Subchannel deleted (t=+10.00970162s)
tlogger.go:133: INFO clientconn.go:1231 [core] [Channel #1270] Channel deleted (t=+10.009752586s)
tlogger.go:133: INFO xds_resolver.go:301 [xds] [xds-resolver 0xc0006f80b0] Shutdown (t=+10.0097689s)
tlogger.go:133: INFO clientconn.go:1302 [core] [Channel #1265 SubChannel #1271] Subchannel Connectivity change to SHUTDOWN (t=+10.00978915s)
tlogger.go:133: INFO clientconn.go:1696 [core] [Channel #1265 SubChannel #1271] Subchannel deleted (t=+10.009798944s)
tlogger.go:133: INFO clientconn.go:1231 [core] [Channel #1265] Channel deleted (t=+10.009836289s)
tlogger.go:133: INFO server.go:866 [core] [Server #1260 ListenSocket #1263] ListenSocket deleted (t=+10.009862258s)
tlogger.go:133: INFO server.go:866 [core] [Server #1261 ListenSocket #1264] ListenSocket deleted (t=+10.009907134s)
tlogger.go:133: INFO server.go:866 [core] [Server #1259 ListenSocket #1262] ListenSocket deleted (t=+10.009929047s)
FAIL
FAIL google.golang.org/grpc/internal/xds/httpfilter/extproc 13.511s
```
1 条评论