Attachment 1978108 Details for Bug 2225888 – build.log

build.log

build.log (text/plain), 32.00 KB, created by Fedora Release Engineering on 2023-07-25 17:59:46 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Fedora Release Engineering

Created: 2023-07-25 17:59:46 UTC

Size: 32.00 KB

patch

obsolete

>18] Subchannel picks a new address "localhost:39023" to connect  (t=+48.019273ms)
>        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #17] Channel Connectivity change to CONNECTING  (t=+48.359628ms)
>        tlogger.go:116: WARNING server.go:901 [core] [Server #11] grpc: Server.Serve failed to create ServerTransport: connection error: desc = "ServerHandshake(\"127.0.0.1:59476\") failed: x509: certificate signed by unknown authority"  (t=+81.614922ms)
>        tlogger.go:116: INFO clientconn.go:1101 [core] [Channel #17 SubChannel #18] Subchannel Connectivity change to TRANSIENT_FAILURE  (t=+81.650714ms)
>        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #17] Channel Connectivity change to TRANSIENT_FAILURE  (t=+81.691273ms)
>        tlogger.go:116: INFO advancedtls_integration_test.go:115 [core] [Channel #20] Channel created  (t=+81.72807ms)
>        tlogger.go:116: INFO clientconn.go:1579 [core] [Channel #20] original dial target is: "localhost:39023"  (t=+81.74189ms)
>        tlogger.go:116: INFO clientconn.go:1586 [core] [Channel #20] parsed dial target is: {Scheme:localhost Authority: Endpoint:39023 URL:{Scheme:localhost Opaque:39023 User: Host: Path: RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}}  (t=+81.76312ms)
>        tlogger.go:116: INFO clientconn.go:1599 [core] [Channel #20] fallback to scheme "passthrough"  (t=+81.774967ms)
>        tlogger.go:116: INFO clientconn.go:1607 [core] [Channel #20] parsed dial target is: {Scheme:passthrough Authority: Endpoint:localhost:39023 URL:{Scheme:passthrough Opaque: User: Host: Path:/localhost:39023 RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}}  (t=+81.789068ms)
>        tlogger.go:116: INFO clientconn.go:263 [core] [Channel #20] Channel authority set to "localhost:39023"  (t=+81.824001ms)
>        tlogger.go:116: INFO resolver_conn_wrapper.go:175 [core] [Channel #20] Resolver state updated: {
>              "Addresses": [
>                {
>                  "Addr": "localhost:39023",
>                  "ServerName": "",
>                  "Attributes": null,
>                  "BalancerAttributes": null,
>                  "Type": 0,
>                  "Metadata": null
>                }
>              ],
>              "ServiceConfig": null,
>              "Attributes": null
>            } (resolver returned new addresses)  (t=+81.868145ms)
>        tlogger.go:116: INFO balancer_conn_wrappers.go:271 [core] [Channel #20] Channel switches to new LB policy "pick_first"  (t=+81.891953ms)
>        tlogger.go:116: INFO clientconn.go:725 [core] [Channel #20 SubChannel #21] Subchannel created  (t=+81.913552ms)
>        tlogger.go:116: INFO clientconn.go:1101 [core] [Channel #20 SubChannel #21] Subchannel Connectivity change to CONNECTING  (t=+81.958435ms)
>        tlogger.go:116: INFO clientconn.go:1212 [core] [Channel #20 SubChannel #21] Subchannel picks a new address "localhost:39023" to connect  (t=+81.975731ms)
>        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #20] Channel Connectivity change to CONNECTING  (t=+82.009408ms)
>        tlogger.go:116: INFO clientconn.go:1101 [core] [Channel #20 SubChannel #21] Subchannel Connectivity change to READY  (t=+111.929079ms)
>        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #20] Channel Connectivity change to READY  (t=+111.969472ms)
>        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #20] Channel Connectivity change to SHUTDOWN  (t=+112.458388ms)
>        tlogger.go:116: INFO clientconn.go:1101 [core] [Channel #20 SubChannel #21] Subchannel Connectivity change to SHUTDOWN  (t=+112.502307ms)
>        tlogger.go:116: INFO clientconn.go:1457 [core] [Channel #20 SubChannel #21] Subchannel deleted  (t=+112.543561ms)
>        tlogger.go:116: INFO clientconn.go:1056 [core] [Channel #20] Channel deleted  (t=+112.56208ms)
>        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #17] Channel Connectivity change to SHUTDOWN  (t=+112.586942ms)
>        tlogger.go:116: INFO clientconn.go:1101 [core] [Channel #17 SubChannel #18] Subchannel Connectivity change to SHUTDOWN  (t=+112.624603ms)
>        tlogger.go:116: INFO clientconn.go:1457 [core] [Channel #17 SubChannel #18] Subchannel deleted  (t=+112.644521ms)
>        tlogger.go:116: INFO clientconn.go:1056 [core] [Channel #17] Channel deleted  (t=+112.661852ms)
>        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #12] Channel Connectivity change to SHUTDOWN  (t=+112.737069ms)
>        tlogger.go:116: INFO clientconn.go:1101 [core] [Channel #12 SubChannel #14] Subchannel Connectivity change to SHUTDOWN  (t=+112.777865ms)
>        tlogger.go:116: INFO clientconn.go:1457 [core] [Channel #12 SubChannel #14] Subchannel deleted  (t=+112.820312ms)
>        tlogger.go:116: INFO clientconn.go:1056 [core] [Channel #12] Channel deleted  (t=+112.835904ms)
>        tlogger.go:116: INFO server.go:737 [core] [Server #11 ListenSocket #13] ListenSocket deleted  (t=+112.921021ms)
>        tlogger.go:116: INFO server.go:598 [core] [Server #24] Server created  (t=+113.049133ms)
>        tlogger.go:116: INFO advancedtls_integration_test.go:115 [core] [Channel #25] Channel created  (t=+113.578556ms)
>        tlogger.go:116: INFO clientconn.go:1579 [core] [Channel #25] original dial target is: "localhost:38137"  (t=+113.603521ms)
>        tlogger.go:116: INFO server.go:786 [core] [Server #24 ListenSocket #26] ListenSocket created  (t=+113.645075ms)
>        tlogger.go:116: INFO clientconn.go:1586 [core] [Channel #25] parsed dial target is: {Scheme:localhost Authority: Endpoint:38137 URL:{Scheme:localhost Opaque:38137 User: Host: Path: RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}}  (t=+113.690872ms)
>        tlogger.go:116: INFO clientconn.go:1599 [core] [Channel #25] fallback to scheme "passthrough"  (t=+113.712693ms)
>        tlogger.go:116: INFO clientconn.go:1607 [core] [Channel #25] parsed dial target is: {Scheme:passthrough Authority: Endpoint:localhost:38137 URL:{Scheme:passthrough Opaque: User: Host: Path:/localhost:38137 RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}}  (t=+113.757373ms)
>        tlogger.go:116: INFO clientconn.go:263 [core] [Channel #25] Channel authority set to "localhost:38137"  (t=+113.779665ms)
>        tlogger.go:116: INFO resolver_conn_wrapper.go:175 [core] [Channel #25] Resolver state updated: {
>              "Addresses": [
>                {
>                  "Addr": "localhost:38137",
>                  "ServerName": "",
>                  "Attributes": null,
>                  "BalancerAttributes": null,
>                  "Type": 0,
>                  "Metadata": null
>                }
>              ],
>              "ServiceConfig": null,
>              "Attributes": null
>            } (resolver returned new addresses)  (t=+113.868837ms)
>        tlogger.go:116: INFO balancer_conn_wrappers.go:271 [core] [Channel #25] Channel switches to new LB policy "pick_first"  (t=+113.930219ms)
>        tlogger.go:116: INFO clientconn.go:725 [core] [Channel #25 SubChannel #27] Subchannel created  (t=+113.979922ms)
>        tlogger.go:116: INFO clientconn.go:1101 [core] [Channel #25 SubChannel #27] Subchannel Connectivity change to CONNECTING  (t=+114.041976ms)
>        tlogger.go:116: INFO clientconn.go:1212 [core] [Channel #25 SubChannel #27] Subchannel picks a new address "localhost:38137" to connect  (t=+114.081876ms)
>        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #25] Channel Connectivity change to CONNECTING  (t=+114.165344ms)
>        tlogger.go:116: INFO clientconn.go:1101 [core] [Channel #25 SubChannel #27] Subchannel Connectivity change to READY  (t=+155.506293ms)
>        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #25] Channel Connectivity change to READY  (t=+155.593476ms)
>        tlogger.go:116: INFO advancedtls_integration_test.go:110 [core] [Channel #30] Channel created  (t=+156.214951ms)
>        tlogger.go:116: INFO clientconn.go:1579 [core] [Channel #30] original dial target is: "localhost:38137"  (t=+156.242092ms)
>        tlogger.go:116: INFO clientconn.go:1586 [core] [Channel #30] parsed dial target is: {Scheme:localhost Authority: Endpoint:38137 URL:{Scheme:localhost Opaque:38137 User: Host: Path: RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}}  (t=+156.280986ms)
>        tlogger.go:116: INFO clientconn.go:1599 [core] [Channel #30] fallback to scheme "passthrough"  (t=+156.292247ms)
>        tlogger.go:116: INFO clientconn.go:1607 [core] [Channel #30] parsed dial target is: {Scheme:passthrough Authority: Endpoint:localhost:38137 URL:{Scheme:passthrough Opaque: User: Host: Path:/localhost:38137 RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}}  (t=+156.310414ms)
>        tlogger.go:116: INFO clientconn.go:263 [core] [Channel #30] Channel authority set to "localhost:38137"  (t=+156.324683ms)
>        tlogger.go:116: INFO resolver_conn_wrapper.go:175 [core] [Channel #30] Resolver state updated: {
>              "Addresses": [
>                {
>                  "Addr": "localhost:38137",
>                  "ServerName": "",
>                  "Attributes": null,
>                  "BalancerAttributes": null,
>                  "Type": 0,
>                  "Metadata": null
>                }
>              ],
>              "ServiceConfig": null,
>              "Attributes": null
>            } (resolver returned new addresses)  (t=+156.388651ms)
>        tlogger.go:116: INFO balancer_conn_wrappers.go:271 [core] [Channel #30] Channel switches to new LB policy "pick_first"  (t=+156.440119ms)
>        tlogger.go:116: INFO clientconn.go:725 [core] [Channel #30 SubChannel #31] Subchannel created  (t=+156.473345ms)
>        tlogger.go:116: INFO picker_wrapper.go:161 [core] blockingPicker: the picked transport is not ready, loop back to repick  (t=+156.533816ms)
>        tlogger.go:116: INFO clientconn.go:1101 [core] [Channel #30 SubChannel #31] Subchannel Connectivity change to CONNECTING  (t=+156.552165ms)
>        tlogger.go:116: INFO clientconn.go:1212 [core] [Channel #30 SubChannel #31] Subchannel picks a new address "localhost:38137" to connect  (t=+156.587099ms)
>        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #30] Channel Connectivity change to CONNECTING  (t=+156.672416ms)
>        tlogger.go:116: WARNING clientconn.go:1279 [core] [Channel #30 SubChannel #31] grpc: addrConn.createTransport failed to connect to {
>              "Addr": "localhost:38137",
>              "ServerName": "localhost:38137",
>              "Attributes": null,
>              "BalancerAttributes": null,
>              "Type": 0,
>              "Metadata": null
>            }. Err: connection error: desc = "transport: authentication handshake failed: x509: certificate signed by unknown authority"  (t=+173.214358ms)
>        tlogger.go:116: INFO clientconn.go:1101 [core] [Channel #30 SubChannel #31] Subchannel Connectivity change to TRANSIENT_FAILURE  (t=+173.27159ms)
>        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #30] Channel Connectivity change to TRANSIENT_FAILURE  (t=+173.305683ms)
>        tlogger.go:116: INFO advancedtls_integration_test.go:115 [core] [Channel #32] Channel created  (t=+173.359201ms)
>        tlogger.go:116: INFO clientconn.go:1579 [core] [Channel #32] original dial target is: "localhost:38137"  (t=+173.380251ms)
>        tlogger.go:116: INFO clientconn.go:1586 [core] [Channel #32] parsed dial target is: {Scheme:localhost Authority: Endpoint:38137 URL:{Scheme:localhost Opaque:38137 User: Host: Path: RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}}  (t=+173.417455ms)
>        tlogger.go:116: INFO clientconn.go:1599 [core] [Channel #32] fallback to scheme "passthrough"  (t=+173.438575ms)
>        tlogger.go:116: INFO clientconn.go:1607 [core] [Channel #32] parsed dial target is: {Scheme:passthrough Authority: Endpoint:localhost:38137 URL:{Scheme:passthrough Opaque: User: Host: Path:/localhost:38137 RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}}  (t=+173.470123ms)
>        tlogger.go:116: INFO clientconn.go:263 [core] [Channel #32] Channel authority set to "localhost:38137"  (t=+173.513065ms)
>        tlogger.go:116: INFO resolver_conn_wrapper.go:175 [core] [Channel #32] Resolver state updated: {
>              "Addresses": [
>                {
>                  "Addr": "localhost:38137",
>                  "ServerName": "",
>                  "Attributes": null,
>                  "BalancerAttributes": null,
>                  "Type": 0,
>                  "Metadata": null
>                }
>              ],
>              "ServiceConfig": null,
>              "Attributes": null
>            } (resolver returned new addresses)  (t=+173.568537ms)
>        tlogger.go:116: INFO balancer_conn_wrappers.go:271 [core] [Channel #32] Channel switches to new LB policy "pick_first"  (t=+173.602179ms)
>        tlogger.go:116: INFO clientconn.go:725 [core] [Channel #32 SubChannel #33] Subchannel created  (t=+173.628376ms)
>        tlogger.go:116: INFO clientconn.go:1101 [core] [Channel #32 SubChannel #33] Subchannel Connectivity change to CONNECTING  (t=+173.694437ms)
>        tlogger.go:116: INFO clientconn.go:1212 [core] [Channel #32 SubChannel #33] Subchannel picks a new address "localhost:38137" to connect  (t=+173.714925ms)
>        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #32] Channel Connectivity change to CONNECTING  (t=+173.772116ms)
>        tlogger.go:116: WARNING server.go:901 [core] [Server #24] grpc: Server.Serve failed to create ServerTransport: connection error: desc = "ServerHandshake(\"127.0.0.1:56188\") failed: remote error: tls: bad certificate"  (t=+174.46693ms)
>        tlogger.go:116: INFO clientconn.go:1101 [core] [Channel #32 SubChannel #33] Subchannel Connectivity change to READY  (t=+213.563331ms)
>        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #32] Channel Connectivity change to READY  (t=+213.617238ms)
>        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #32] Channel Connectivity change to SHUTDOWN  (t=+214.000053ms)
>        tlogger.go:116: INFO clientconn.go:1101 [core] [Channel #32 SubChannel #33] Subchannel Connectivity change to SHUTDOWN  (t=+214.03487ms)
>        tlogger.go:116: INFO clientconn.go:1457 [core] [Channel #32 SubChannel #33] Subchannel deleted  (t=+214.055866ms)
>        tlogger.go:116: INFO clientconn.go:1056 [core] [Channel #32] Channel deleted  (t=+214.08807ms)
>        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #30] Channel Connectivity change to SHUTDOWN  (t=+214.105951ms)
>        tlogger.go:116: INFO clientconn.go:1101 [core] [Channel #30 SubChannel #31] Subchannel Connectivity change to SHUTDOWN  (t=+214.127895ms)
>        tlogger.go:116: INFO clientconn.go:1457 [core] [Channel #30 SubChannel #31] Subchannel deleted  (t=+214.14841ms)
>        tlogger.go:116: INFO clientconn.go:1056 [core] [Channel #30] Channel deleted  (t=+214.163713ms)
>        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #25] Channel Connectivity change to SHUTDOWN  (t=+214.192638ms)
>        tlogger.go:116: INFO clientconn.go:1101 [core] [Channel #25 SubChannel #27] Subchannel Connectivity change to SHUTDOWN  (t=+214.214141ms)
>        tlogger.go:116: INFO clientconn.go:1457 [core] [Channel #25 SubChannel #27] Subchannel deleted  (t=+214.231971ms)
>        tlogger.go:116: INFO clientconn.go:1056 [core] [Channel #25] Channel deleted  (t=+214.248577ms)
>        tlogger.go:116: INFO server.go:737 [core] [Server #24 ListenSocket #26] ListenSocket deleted  (t=+214.314592ms)
>        tlogger.go:116: INFO server.go:598 [core] [Server #36] Server created  (t=+214.510127ms)
>        tlogger.go:116: INFO advancedtls_integration_test.go:115 [core] [Channel #37] Channel created  (t=+214.929919ms)
>        tlogger.go:116: INFO clientconn.go:1579 [core] [Channel #37] original dial target is: "localhost:35169"  (t=+214.956385ms)
>        tlogger.go:116: INFO clientconn.go:1586 [core] [Channel #37] parsed dial target is: {Scheme:localhost Authority: Endpoint:35169 URL:{Scheme:localhost Opaque:35169 User: Host: Path: RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}}  (t=+214.988213ms)
>        tlogger.go:116: INFO clientconn.go:1599 [core] [Channel #37] fallback to scheme "passthrough"  (t=+215.009425ms)
>        tlogger.go:116: INFO clientconn.go:1607 [core] [Channel #37] parsed dial target is: {Scheme:passthrough Authority: Endpoint:localhost:35169 URL:{Scheme:passthrough Opaque: User: Host: Path:/localhost:35169 RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}}  (t=+215.035565ms)
>        tlogger.go:116: INFO clientconn.go:263 [core] [Channel #37] Channel authority set to "localhost:35169"  (t=+215.057881ms)
>        tlogger.go:116: INFO resolver_conn_wrapper.go:175 [core] [Channel #37] Resolver state updated: {
>              "Addresses": [
>                {
>                  "Addr": "localhost:35169",
>                  "ServerName": "",
>                  "Attributes": null,
>                  "BalancerAttributes": null,
>                  "Type": 0,
>                  "Metadata": null
>                }
>              ],
>              "ServiceConfig": null,
>              "Attributes": null
>            } (resolver returned new addresses)  (t=+215.126162ms)
>        tlogger.go:116: INFO balancer_conn_wrappers.go:271 [core] [Channel #37] Channel switches to new LB policy "pick_first"  (t=+215.158401ms)
>        tlogger.go:116: INFO clientconn.go:725 [core] [Channel #37 SubChannel #38] Subchannel created  (t=+215.185431ms)
>        tlogger.go:116: INFO clientconn.go:1101 [core] [Channel #37 SubChannel #38] Subchannel Connectivity change to CONNECTING  (t=+215.24887ms)
>        tlogger.go:116: INFO clientconn.go:1212 [core] [Channel #37 SubChannel #38] Subchannel picks a new address "localhost:35169" to connect  (t=+215.269844ms)
>        tlogger.go:116: INFO server.go:786 [core] [Server #36 ListenSocket #39] ListenSocket created  (t=+215.714958ms)
>        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #37] Channel Connectivity change to CONNECTING  (t=+215.762899ms)
>        tlogger.go:116: INFO clientconn.go:1101 [core] [Channel #37 SubChannel #38] Subchannel Connectivity change to READY  (t=+254.46276ms)
>        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #37] Channel Connectivity change to READY  (t=+254.532036ms)
>        tlogger.go:116: INFO advancedtls_integration_test.go:110 [core] [Channel #42] Channel created  (t=+255.409816ms)
>        tlogger.go:116: INFO clientconn.go:1579 [core] [Channel #42] original dial target is: "localhost:35169"  (t=+255.443638ms)
>        tlogger.go:116: INFO clientconn.go:1586 [core] [Channel #42] parsed dial target is: {Scheme:localhost Authority: Endpoint:35169 URL:{Scheme:localhost Opaque:35169 User: Host: Path: RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}}  (t=+255.495622ms)
>        tlogger.go:116: INFO clientconn.go:1599 [core] [Channel #42] fallback to scheme "passthrough"  (t=+255.516ms)
>        tlogger.go:116: INFO clientconn.go:1607 [core] [Channel #42] parsed dial target is: {Scheme:passthrough Authority: Endpoint:localhost:35169 URL:{Scheme:passthrough Opaque: User: Host: Path:/localhost:35169 RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}}  (t=+255.548946ms)
>        tlogger.go:116: INFO clientconn.go:263 [core] [Channel #42] Channel authority set to "localhost:35169"  (t=+255.573043ms)
>        tlogger.go:116: INFO resolver_conn_wrapper.go:175 [core] [Channel #42] Resolver state updated: {
>              "Addresses": [
>                {
>                  "Addr": "localhost:35169",
>                  "ServerName": "",
>                  "Attributes": null,
>                  "BalancerAttributes": null,
>                  "Type": 0,
>                  "Metadata": null
>                }
>              ],
>              "ServiceConfig": null,
>              "Attributes": null
>            } (resolver returned new addresses)  (t=+256.977435ms)
>        tlogger.go:116: INFO balancer_conn_wrappers.go:271 [core] [Channel #42] Channel switches to new LB policy "pick_first"  (t=+257.099327ms)
>        tlogger.go:116: INFO clientconn.go:725 [core] [Channel #42 SubChannel #43] Subchannel created  (t=+257.142786ms)
>        tlogger.go:116: INFO clientconn.go:1101 [core] [Channel #42 SubChannel #43] Subchannel Connectivity change to CONNECTING  (t=+257.399446ms)
>        tlogger.go:116: INFO clientconn.go:1212 [core] [Channel #42 SubChannel #43] Subchannel picks a new address "localhost:35169" to connect  (t=+257.430075ms)
>        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #42] Channel Connectivity change to CONNECTING  (t=+258.001535ms)
>        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #42] Channel Connectivity change to SHUTDOWN  (t=+266.958834ms)
>        tlogger.go:116: INFO clientconn.go:1101 [core] [Channel #42 SubChannel #43] Subchannel Connectivity change to SHUTDOWN  (t=+267.024868ms)
>        tlogger.go:116: INFO clientconn.go:1457 [core] [Channel #42 SubChannel #43] Subchannel deleted  (t=+267.084499ms)
>        tlogger.go:116: INFO clientconn.go:1056 [core] [Channel #42] Channel deleted  (t=+267.119732ms)
>        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #37] Channel Connectivity change to SHUTDOWN  (t=+267.186647ms)
>        tlogger.go:116: WARNING clientconn.go:1279 [core] [Channel #42 SubChannel #43] grpc: addrConn.createTransport failed to connect to {
>              "Addr": "localhost:35169",
>              "ServerName": "localhost:35169",
>              "Attributes": null,
>              "BalancerAttributes": null,
>              "Type": 0,
>              "Metadata": null
>            }. Err: connection error: desc = "transport: Error while dialing dial tcp [::1]:35169: connect: connection refused"  (t=+267.238315ms)
>        tlogger.go:116: INFO clientconn.go:1101 [core] [Channel #37 SubChannel #38] Subchannel Connectivity change to SHUTDOWN  (t=+267.336065ms)
>        tlogger.go:116: INFO clientconn.go:1457 [core] [Channel #37 SubChannel #38] Subchannel deleted  (t=+267.378322ms)
>        tlogger.go:116: INFO clientconn.go:1056 [core] [Channel #37] Channel deleted  (t=+267.399966ms)
>        tlogger.go:116: INFO server.go:737 [core] [Server #36 ListenSocket #39] ListenSocket deleted  (t=+267.468663ms)
>        --- FAIL: Test/End2End/test_client_custom_verification (0.05s)
>            advancedtls_integration_test.go:408: client failed to connect to localhost:35169. Error: context deadline exceeded
>        tlogger.go:116: INFO server.go:598 [core] [Server #44] Server created  (t=+267.727082ms)
>        tlogger.go:116: INFO advancedtls_integration_test.go:115 [core] [Channel #45] Channel created  (t=+268.165254ms)
>        tlogger.go:116: INFO clientconn.go:1579 [core] [Channel #45] original dial target is: "localhost:36927"  (t=+268.192986ms)
>        tlogger.go:116: INFO clientconn.go:1586 [core] [Channel #45] parsed dial target is: {Scheme:localhost Authority: Endpoint:36927 URL:{Scheme:localhost Opaque:36927 User: Host: Path: RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}}  (t=+268.227236ms)
>        tlogger.go:116: INFO clientconn.go:1599 [core] [Channel #45] fallback to scheme "passthrough"  (t=+268.247553ms)
>        tlogger.go:116: INFO server.go:786 [core] [Server #44 ListenSocket #46] ListenSocket created  (t=+268.270837ms)
>        tlogger.go:116: INFO clientconn.go:1607 [core] [Channel #45] parsed dial target is: {Scheme:passthrough Authority: Endpoint:localhost:36927 URL:{Scheme:passthrough Opaque: User: Host: Path:/localhost:36927 RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}}  (t=+268.321878ms)
>        tlogger.go:116: INFO clientconn.go:263 [core] [Channel #45] Channel authority set to "localhost:36927"  (t=+268.353649ms)
>        tlogger.go:116: INFO resolver_conn_wrapper.go:175 [core] [Channel #45] Resolver state updated: {
>              "Addresses": [
>                {
>                  "Addr": "localhost:36927",
>                  "ServerName": "",
>                  "Attributes": null,
>                  "BalancerAttributes": null,
>                  "Type": 0,
>                  "Metadata": null
>                }
>              ],
>              "ServiceConfig": null,
>              "Attributes": null
>            } (resolver returned new addresses)  (t=+268.429818ms)
>        tlogger.go:116: INFO balancer_conn_wrappers.go:271 [core] [Channel #45] Channel switches to new LB policy "pick_first"  (t=+268.487356ms)
>        tlogger.go:116: INFO clientconn.go:725 [core] [Channel #45 SubChannel #47] Subchannel created  (t=+268.521525ms)
>        tlogger.go:116: INFO clientconn.go:1101 [core] [Channel #45 SubChannel #47] Subchannel Connectivity change to CONNECTING  (t=+268.589379ms)
>        tlogger.go:116: INFO clientconn.go:1212 [core] [Channel #45 SubChannel #47] Subchannel picks a new address "localhost:36927" to connect  (t=+268.654988ms)
>        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #45] Channel Connectivity change to CONNECTING  (t=+268.737281ms)
>        tlogger.go:116: WARNING server.go:901 [core] [Server #44] grpc: Server.Serve failed to create ServerTransport: connection error: desc = "ServerHandshake(\"127.0.0.1:51654\") failed: custom authz check fails"  (t=+309.901988ms)
>        tlogger.go:116: INFO clientconn.go:1101 [core] [Channel #45 SubChannel #47] Subchannel Connectivity change to TRANSIENT_FAILURE  (t=+309.964405ms)
>        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #45] Channel Connectivity change to TRANSIENT_FAILURE  (t=+310.024629ms)
>        tlogger.go:116: INFO clientconn.go:1101 [core] [Channel #45 SubChannel #47] Subchannel Connectivity change to IDLE  (t=+1.310223503s)
>        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #45] Channel Connectivity change to IDLE  (t=+1.310310167s)
>        tlogger.go:116: INFO clientconn.go:1101 [core] [Channel #45 SubChannel #47] Subchannel Connectivity change to CONNECTING  (t=+1.310383681s)
>        tlogger.go:116: INFO clientconn.go:1212 [core] [Channel #45 SubChannel #47] Subchannel picks a new address "localhost:36927" to connect  (t=+1.310411737s)
>        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #45] Channel Connectivity change to CONNECTING  (t=+1.310634072s)
>        tlogger.go:116: WARNING server.go:901 [core] [Server #44] grpc: Server.Serve failed to create ServerTransport: connection error: desc = "ServerHandshake(\"127.0.0.1:51656\") failed: custom authz check fails"  (t=+1.351006969s)
>        tlogger.go:116: INFO clientconn.go:1101 [core] [Channel #45 SubChannel #47] Subchannel Connectivity change to TRANSIENT_FAILURE  (t=+1.351121737s)
>        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #45] Channel Connectivity change to TRANSIENT_FAILURE  (t=+1.351187559s)
>        tlogger.go:116: INFO clientconn.go:1101 [core] [Channel #45 SubChannel #47] Subchannel Connectivity change to IDLE  (t=+2.907948997s)
>        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #45] Channel Connectivity change to IDLE  (t=+2.908011171s)
>        tlogger.go:116: INFO clientconn.go:1101 [core] [Channel #45 SubChannel #47] Subchannel Connectivity change to CONNECTING  (t=+2.908065193s)
>        tlogger.go:116: INFO clientconn.go:1212 [core] [Channel #45 SubChannel #47] Subchannel picks a new address "localhost:36927" to connect  (t=+2.908111486s)
>        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #45] Channel Connectivity change to CONNECTING  (t=+2.908236528s)
>        tlogger.go:116: WARNING server.go:901 [core] [Server #44] grpc: Server.Serve failed to create ServerTransport: connection error: desc = "ServerHandshake(\"127.0.0.1:51670\") failed: custom authz check fails"  (t=+2.955648683s)
>        tlogger.go:116: INFO clientconn.go:1101 [core] [Channel #45 SubChannel #47] Subchannel Connectivity change to TRANSIENT_FAILURE  (t=+2.955729584s)
>        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #45] Channel Connectivity change to TRANSIENT_FAILURE  (t=+2.955780293s)
>        tlogger.go:116: INFO clientconn.go:1101 [core] [Channel #45 SubChannel #47] Subchannel Connectivity change to IDLE  (t=+5.133185696s)
>        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #45] Channel Connectivity change to IDLE  (t=+5.133258181s)
>        tlogger.go:116: INFO clientconn.go:1101 [core] [Channel #45 SubChannel #47] Subchannel Connectivity change to CONNECTING  (t=+5.133296464s)
>        tlogger.go:116: INFO clientconn.go:1212 [core] [Channel #45 SubChannel #47] Subchannel picks a new address "localhost:36927" to connect  (t=+5.133318979s)
>        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #45] Channel Connectivity change to CONNECTING  (t=+5.133464928s)
>        tlogger.go:116: WARNING server.go:901 [core] [Server #44] grpc: Server.Serve failed to create ServerTransport: connection error: desc = "ServerHandshake(\"127.0.0.1:51678\") failed: custom authz check fails"  (t=+5.169444695s)
>        tlogger.go:116: INFO clientconn.go:1101 [core] [Channel #45 SubChannel #47] Subchannel Connectivity change to TRANSIENT_FAILURE  (t=+5.169488441s)
>        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #45] Channel Connectivity change to TRANSIENT_FAILURE  (t=+5.169513314s)
>        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #45] Channel Connectivity change to SHUTDOWN  (t=+5.268903596s)
>        tlogger.go:116: INFO clientconn.go:1101 [core] [Channel #45 SubChannel #47] Subchannel Connectivity change to SHUTDOWN  (t=+5.268975221s)
>        tlogger.go:116: INFO clientconn.go:1457 [core] [Channel #45 SubChannel #47] Subchannel deleted  (t=+5.269007712s)
>        tlogger.go:116: INFO clientconn.go:1056 [core] [Channel #45] Channel deleted  (t=+5.269027058s)
>        tlogger.go:116: INFO server.go:737 [core] [Server #44 ListenSocket #46] ListenSocket deleted  (t=+5.269179927s)
>        --- FAIL: Test/End2End/TestServerCustomVerification (5.00s)
>            advancedtls_integration_test.go:391: client failed to connect to localhost:36927. Error: context deadline exceeded
>FAIL
>exit status 1
>FAIL	google.golang.org/grpc/security/advancedtls	8.896s
>error: Bad exit status from /var/tmp/rpm-tmp.H7BavM (%check)
>    Bad exit status from /var/tmp/rpm-tmp.H7BavM (%check)
>RPM build errors:
>Child return code was: 1
>EXCEPTION: [Error('Command failed: \n # /usr/bin/systemd-nspawn -q -M f1a5449d7d654348be482cdf348e9cd5 -D /var/lib/mock/f39-build-44287105-5275225/root -a -u mockbuild --capability=cap_ipc_lock --bind=/tmp/mock-resolv.0qr7lx43:/etc/resolv.conf --bind=/dev/btrfs-control --bind=/dev/mapper/control --bind=/dev/loop-control --bind=/dev/loop0 --bind=/dev/loop1 --bind=/dev/loop2 --bind=/dev/loop3 --bind=/dev/loop4 --bind=/dev/loop5 --bind=/dev/loop6 --bind=/dev/loop7 --bind=/dev/loop8 --bind=/dev/loop9 --bind=/dev/loop10 --bind=/dev/loop11 --console=pipe --setenv=TERM=vt100 --setenv=SHELL=/bin/bash --setenv=HOME=/builddir --setenv=HOSTNAME=mock --setenv=PATH=/usr/bin:/bin:/usr/sbin:/sbin --setenv=PROMPT_COMMAND=printf "\\033]0;<mock-chroot>\\007" --setenv=PS1=<mock-chroot> \\s-\\v\\$  --setenv=LANG=C.UTF-8 --resolv-conf=off bash --login -c /usr/bin/rpmbuild -ba --noprep --noclean --target x86_64 --nodeps /builddir/build/SPECS/golang-google-grpc.spec\n', 1)]
>Traceback (most recent call last):
>  File "/usr/lib/python3.11/site-packages/mockbuild/trace_decorator.py", line 93, in trace
>    result = func(*args, **kw)
>             ^^^^^^^^^^^^^^^^^
>  File "/usr/lib/python3.11/site-packages/mockbuild/util.py", line 597, in do_with_status
>    raise exception.Error("Command failed: \n # %s\n%s" % (command, output), child.returncode)
>mockbuild.exception.Error: Command failed: 
> # /usr/bin/systemd-nspawn -q -M f1a5449d7d654348be482cdf348e9cd5 -D /var/lib/mock/f39-build-44287105-5275225/root -a -u mockbuild --capability=cap_ipc_lock --bind=/tmp/mock-resolv.0qr7lx43:/etc/resolv.conf --bind=/dev/btrfs-control --bind=/dev/mapper/control --bind=/dev/loop-control --bind=/dev/loop0 --bind=/dev/loop1 --bind=/dev/loop2 --bind=/dev/loop3 --bind=/dev/loop4 --bind=/dev/loop5 --bind=/dev/loop6 --bind=/dev/loop7 --bind=/dev/loop8 --bind=/dev/loop9 --bind=/dev/loop10 --bind=/dev/loop11 --console=pipe --setenv=TERM=vt100 --setenv=SHELL=/bin/bash --setenv=HOME=/builddir --setenv=HOSTNAME=mock --setenv=PATH=/usr/bin:/bin:/usr/sbin:/sbin --setenv=PROMPT_COMMAND=printf "\033]0;<mock-chroot>\007" --setenv=PS1=<mock-chroot> \s-\v\$  --setenv=LANG=C.UTF-8 --resolv-conf=off bash --login -c /usr/bin/rpmbuild -ba --noprep --noclean --target x86_64 --nodeps /builddir/build/SPECS/golang-google-grpc.spec
>

Actions: View

Attachments on bug 2225888: 1978108 | 1978109 | 1978110