Occasional e2e test failures

ondrej-fabry commented 4 years ago

On travis, some e2e tests are failing occasionally. Here are some recent failures:

FAIL: TestTapInterfaceConn (70.83s) https://travis-ci.com/ligato/vpp-agent/builds/141046179
FAIL: TestTapInterfaceConn (70.74s)
https://travis-ci.com/ligato/vpp-agent/builds/141047198
FAIL: TestSourceNAT (15.87s) https://travis-ci.com/ligato/vpp-agent/builds/141107514

Log output for failed TestSourceNAT
``` --- FAIL: TestSourceNAT (15.87s) e2e_test.go:612: VPP start OK (PID: 11018) e2e_test.go:156: Using docker client endpoint: unix:///var/run/docker.sock e2e_test.go:612: VPP-Agent start OK (PID: 11019) e2e_test.go:564: agent ready, took 101.294308ms e2e_test.go:299: exec: vppctl show nat44 addresses e2e_test.go:299: exec: vppctl show nat44 addresses microservice_test.go:177: Linux ping 80.80.80.10: sent=5, received=3, loss=40% e2e_test.go:299: exec: vppctl clear trace e2e_test.go:299: exec: vppctl trace add virtio-input 100 e2e_test.go:299: exec: vppctl show trace e2e_test.go:299: exec: vppctl clear trace e2e_test.go:299: exec: vppctl trace add virtio-input 100 e2e_test.go:299: exec: vppctl show trace testing_t_support.go:22: /home/travis/gopath/pkg/mod/github.com/onsi/gomega@v1.4.1/internal/assertion/assertion.go:69 +0x1b4 github.com/onsi/gomega/internal/assertion.(*Assertion).Should(0xc000174ac0, 0xf3be20, 0x16000f0, 0x0, 0x0, 0x0, 0xb) /home/travis/gopath/pkg/mod/github.com/onsi/gomega@v1.4.1/internal/assertion/assertion.go:27 +0xac go.ligato.io/vpp-agent/v2/tests/e2e.TestSourceNAT(0xc000528000) /home/travis/gopath/src/go.ligato.io/vpp-agent/tests/e2e/050_nat_test.go:189 +0x19d4 testing.tRunner(0xc000528000, 0xe37580) /home/travis/.gimme/versions/go1.13.5.linux.amd64/src/testing/testing.go:909 +0xc9 created by testing.(*T).Run /home/travis/.gimme/versions/go1.13.5.linux.amd64/src/testing/testing.go:960 +0x350 Expected success, but got an error: <*errors.errorString | 0xc00027c550>: { s: "communication with 80.80.80.10:8000 timed out", } communication with 80.80.80.10:8000 timed out e2e_test.go:208: ----------------- e2e_test.go:633: VPP-Agent exit OK e2e_test.go:633: VPP exit OK ``` > full log here: https://pastebin.com/raw/wcHPBzwt
FAIL: TestTapInterfaceConn (69.99s) https://travis-ci.com/ligato/vpp-agent/jobs/268018518

cc @milanlenco

ondrej-fabry commented 4 years ago

Test TestTapInterfaceConn keeps running into some bug with messed up name for VPP TAP interface:

config/linux/interfaces/v2/interface/linux-tap (CREATE): LinkByName "ta\x04": Link not found

Full log output for test

``` === RUN TestTapInterfaceConn vlib_plugin_early_init:361: plugin path /usr/lib/x86_64-linux-gnu/vpp_plugins:/usr/lib/vpp_plugins load_one_plugin:189: Loaded plugin: abf_plugin.so (Access Control List (ACL) Based Forwarding) load_one_plugin:189: Loaded plugin: acl_plugin.so (Access Control Lists (ACL)) load_one_plugin:189: Loaded plugin: avf_plugin.so (Intel Adaptive Virtual Function (AVF) Device Driver) load_one_plugin:189: Loaded plugin: cdp_plugin.so (Cisco Discovery Protocol (CDP)) load_one_plugin:189: Loaded plugin: crypto_ia32_plugin.so (Intel IA32 Software Crypto Engine) load_one_plugin:189: Loaded plugin: crypto_ipsecmb_plugin.so (Intel IPSEC Multi-buffer Crypto Engine) load_one_plugin:189: Loaded plugin: crypto_openssl_plugin.so (OpenSSL Crypto Engine) load_one_plugin:189: Loaded plugin: ct6_plugin.so (IPv6 Connection Tracker) load_one_plugin:106: Plugin disabled: dpdk_plugin.so load_one_plugin:189: Loaded plugin: flowprobe_plugin.so (Flow per Packet) load_one_plugin:189: Loaded plugin: gbp_plugin.so (Group Based Policy (GBP)) load_one_plugin:189: Loaded plugin: gtpu_plugin.so (GPRS Tunnelling Protocol, User Data (GTPv1-U)) load_one_plugin:189: Loaded plugin: igmp_plugin.so (Internet Group Management Protocol (IGMP)) load_one_plugin:189: Loaded plugin: ikev2_plugin.so (Internet Key Exchange (IKEv2) Protocol) load_one_plugin:189: Loaded plugin: ila_plugin.so (Identifier Locator Addressing (ILA) for IPv6) load_one_plugin:189: Loaded plugin: ioam_plugin.so (Inbound Operations, Administration, and Maintenance (OAM)) load_one_plugin:117: Plugin disabled (default): ixge_plugin.so load_one_plugin:189: Loaded plugin: l2e_plugin.so (Layer 2 (L2) Emulation) load_one_plugin:189: Loaded plugin: lacp_plugin.so (Link Aggregation Control Protocol (LACP)) load_one_plugin:189: Loaded plugin: lb_plugin.so (Load Balancer (LB)) load_one_plugin:189: Loaded plugin: mactime_plugin.so (Time-based MAC Source Address Filter) load_one_plugin:189: Loaded plugin: map_plugin.so (Mapping of Address and Port (MAP)) load_one_plugin:189: Loaded plugin: memif_plugin.so (Packet Memory Interface (memif) -- Experimental) load_one_plugin:189: Loaded plugin: nat_plugin.so (Network Address Translation (NAT)) load_one_plugin:189: Loaded plugin: nsh_plugin.so (Network Service Header (NSH)) load_one_plugin:189: Loaded plugin: nsim_plugin.so (Network Delay Simulator) load_one_plugin:189: Loaded plugin: perfmon_plugin.so (Performance Monitor) load_one_plugin:189: Loaded plugin: pppoe_plugin.so (PPP over Ethernet (PPPoE)) load_one_plugin:189: Loaded plugin: quic_plugin.so (Quic Transport Protocol) load_one_plugin:189: Loaded plugin: rdma_plugin.so (RDMA IBverbs Device Driver) load_one_plugin:189: Loaded plugin: srv6ad_plugin.so (Dynamic Segment Routing for IPv6 (SRv6) Proxy) load_one_plugin:189: Loaded plugin: srv6am_plugin.so (Masquerading Segment Routing for IPv6 (SRv6) Proxy) load_one_plugin:189: Loaded plugin: srv6as_plugin.so (Static Segment Routing for IPv6 (SRv6) Proxy) load_one_plugin:189: Loaded plugin: stn_plugin.so (VPP Steals the NIC (STN) for Container Integration) load_one_plugin:189: Loaded plugin: svs_plugin.so (Source Virtual Routing and Fowarding (VRF) Select) load_one_plugin:189: Loaded plugin: tlsmbedtls_plugin.so (Transport Layer Security (TLS) Engine, Mbedtls Based) load_one_plugin:189: Loaded plugin: tlsopenssl_plugin.so (Transport Layer Security (TLS) Engine, OpenSSL Based) load_one_plugin:117: Plugin disabled (default): unittest_plugin.so load_one_plugin:189: Loaded plugin: vmxnet3_plugin.so (VMWare Vmxnet3 Device Driver) /usr/bin/vpp[5382]: clib_elf_parse_file: open `linux-vdso.so.1': No such file or directory /usr/bin/vpp[5382]: load_one_vat_plugin:67: Loaded plugin: mactime_test_plugin.so /usr/bin/vpp[5382]: load_one_vat_plugin:67: Loaded plugin: vmxnet3_test_plugin.so /usr/bin/vpp[5382]: load_one_vat_plugin:67: Loaded plugin: nat_test_plugin.so /usr/bin/vpp[5382]: load_one_vat_plugin:67: Loaded plugin: acl_test_plugin.so /usr/bin/vpp[5382]: load_one_vat_plugin:67: Loaded plugin: lb_test_plugin.so /usr/bin/vpp[5382]: load_one_vat_plugin:67: Loaded plugin: memif_test_plugin.so /usr/bin/vpp[5382]: load_one_vat_plugin:67: Loaded plugin: gtpu_test_plugin.so /usr/bin/vpp[5382]: load_one_vat_plugin:67: Loaded plugin: pppoe_test_plugin.so /usr/bin/vpp[5382]: load_one_vat_plugin:67: Loaded plugin: nsh_test_plugin.so /usr/bin/vpp[5382]: load_one_vat_plugin:67: Loaded plugin: stn_test_plugin.so /usr/bin/vpp[5382]: load_one_vat_plugin:67: Loaded plugin: lacp_test_plugin.so /usr/bin/vpp[5382]: load_one_vat_plugin:67: Loaded plugin: avf_test_plugin.so /usr/bin/vpp[5382]: load_one_vat_plugin:67: Loaded plugin: cdp_test_plugin.so /usr/bin/vpp[5382]: load_one_vat_plugin:67: Loaded plugin: nsim_test_plugin.so /usr/bin/vpp[5382]: load_one_vat_plugin:67: Loaded plugin: ct6_test_plugin.so /usr/bin/vpp[5382]: load_one_vat_plugin:67: Loaded plugin: flowprobe_test_plugin.so /usr/bin/vpp[5382]: load_one_vat_plugin:67: Loaded plugin: ikev2_test_plugin.so /usr/bin/vpp[5382]: load_one_vat_plugin:67: Loaded plugin: ioam_test_plugin.so flag provided but not defined: -test.coverprofile __ _ _____ ___ _______ ____ ____ ___ / /_ | |/ / _ \/ _ /___/ _ '/ _ '/ -_/ _ / __/ vpp-agent v3.1.0-dev |___/ .__/ .__/ \_'_/\_' /\__/_//_\__/ Tue Feb 11 19:21:23 UTC 2020 (just now) /_/ /_/ /___/ unknown@unknown (go1.13.7 linux/amd64) time="2020-02-11 19:21:23.84175" level=info msg="Starting agent version: v3.1.0-dev" BuildDate="Tue Feb 11 19:21:23 UTC 2020" CommitHash=unknown loc="agent/agent.go(134)" logger=agent time="2020-02-11 19:21:23.84262" level=info msg="ETCD config not found, skip loading this plugin" loc="etcd/plugin_impl_etcd.go(293)" logger=etcd time="2020-02-11 19:21:23.84272" level=info msg="Consul config not found, skip loading this plugin" loc="consul/plugin.go(138)" logger=consul time="2020-02-11 19:21:23.84327" level=info msg="Redis config not found, skip loading this plugin" loc="redis/plugin_impl_redis.go(123)" logger=redis time="2020-02-11 19:21:23.85043" level=info msg="VPP version: 19.04.4-rc0~4-g8f2ac2b64~b3" ClientID=0 PID=5382 loc="govppmux/plugin_impl_govppmux.go(304)" logger=govpp time="2020-02-11 19:21:23.85278" level=info msg="starting VPP proxy" loc="govppmux/plugin_impl_govppmux.go(395)" logger=govpp 2020/02/11 19:21:23 rpc.Register: method "Connect" has 2 input parameters; needs exactly three 2020/02/11 19:21:23 rpc.Register: method "Disconnect" has 1 input parameters; needs exactly three 2020/02/11 19:21:23 rpc.Register: method "Connect" has 2 input parameters; needs exactly three 2020/02/11 19:21:23 rpc.Register: method "Disconnect" has 1 input parameters; needs exactly three time="2020-02-11 19:21:23.85416" level=info msg="VPP proxy ready" loc="govppmux/plugin_impl_govppmux.go(169)" logger=govpp time="2020-02-11 19:21:23.85466" level=info msg="Namespace plugin initialized" loc="nsplugin/ns_plugin.go(111)" logger=linux-nsplugin time="2020-02-11 19:21:23.85503" level=info msg="kafka config not found - skip loading this plugin" loc="kafka/plugin_impl_kafka.go(73)" logger=kafka time="2020-02-11 19:21:23.85705" level=info msg="registering grpc reflection service" loc="orchestrator/orchestrator.go(87)" logger=orchestrator time="2020-02-11 19:21:23.85732" level=info msg="Watch starting for 33 registered NB prefixes" loc="orchestrator/orchestrator.go(96)" logger=dispatcher time="2020-02-11 19:21:23.85841" level=info msg="Listening on http://0.0.0.0:9191" loc="rest/plugin_impl_rest.go(109)" logger=http time="2020-02-11 19:21:23.85885" level=info msg="Agent plugin state update." lastErr="" loc="statuscheck/plugin_impl_statuscheck.go(183)" logger=status-check plugin=govpp state=ok time="2020-02-11T19:21:23Z" level=info msg="enabling statsRPC service" time="2020-02-11T19:21:23Z" level=info msg="enabling binapiRPC service" time="2020-02-11 19:21:23.86178" level=info msg="HTTP not set, skip exposing GRPC services" loc="grpc/plugin_impl_grpc.go(119)" logger=grpc time="2020-02-11 19:21:23.86192" level=info msg="Listening GRPC on: 127.0.0.1:9111" loc="grpc/plugin_impl_grpc.go(127)" logger=grpc time="2020-02-11 19:21:23.86284" level=info msg="Starting health http-probe on port 9191" loc="probe/plugin_impl_probe.go(75)" logger=probe time="2020-02-11 19:21:23.86299" level=info msg="Unable to register prometheus-probe handler, Prometheus is nil" loc="probe/plugin_impl_probe.go(87)" logger=probe time="2020-02-11 19:21:23.86312" level=info msg="Serving /metrics on port 9191" loc="prometheus/plugin_impl_prometheus.go(88)" logger=prometheus time="2020-02-11 19:21:23.86326" level=warning msg="No registrations, skipping resync" loc="resync/plugin_impl_resync.go(98)" logger=resync time="2020-02-11 19:21:23.86334" level=info msg="Agent plugin state update." lastErr="" loc="statuscheck/plugin_impl_statuscheck.go(183)" logger=status-check plugin=VPPAgent state=ok time="2020-02-11 19:21:23.86341" level=info msg="Agent started with 38 plugins (took 21ms)" loc="agent/agent.go(179)" logger=agent time="2020-02-11 19:21:23.93334" level=error msg="failed to retrieve values: dumping VPP L3XCs failed: unsupported" descriptor=vpp-l3xc loc="kvscheduler/refresh.go(121)" logger=kvscheduler +======================================================================================================================+ | #0 - NB Transaction DownstreamResync | +======================================================================================================================+ * transaction arguments: - seqNum: 0 - type: NB Transaction, SB Sync o----------------------------------------------------------------------------------------------------------------------o * executed operations: x----------------------------------------------------------------------------------------------------------------------x | #0 - NB Transaction took 13ms | x----------------------------------------------------------------------------------------------------------------------x +======================================================================================================================+ | #1 - SB Notification | +======================================================================================================================+ * transaction arguments: - seqNum: 1 - type: SB Notification - values: - key: linux/microservice/e2e-test-microservice1 val: o----------------------------------------------------------------------------------------------------------------------o * executed operations (2020-02-11 19:21:24.259 +0000 UTC -> 2020-02-11 19:21:24.259 +0000 UTC, dur: 0s): 1. CREATE [OBTAINED]: - key: linux/microservice/e2e-test-microservice1 - value: x----------------------------------------------------------------------------------------------------------------------x | #1 - SB Notification took 100µs | x----------------------------------------------------------------------------------------------------------------------x time="2020-02-11 19:21:24.25910" level=info msg="Transaction 1 successful!" loc="kvscheduler/txn_process.go(402)" logger=kvscheduler +======================================================================================================================+ | #2 - NB Transaction | +======================================================================================================================+ * transaction arguments: - seqNum: 2 - type: NB Transaction - values: - key: config/linux/interfaces/v2/interface/linux-tap val: { name:"linux-tap" type:TAP_TO_VPP namespace: host_if_name:"tap" enabled:true ip_addresses:"192.168.1.2/30" tap: } - key: config/vpp/v2/interfaces/vpp-tap val: { name:"vpp-tap" type:TAP enabled:true ip_addresses:"192.168.1.1/30" tap: } o----------------------------------------------------------------------------------------------------------------------o * executed operations (2020-02-11 19:21:24.261 +0000 UTC -> 2020-02-11 19:21:24.322 +0000 UTC, dur: 62ms): 1. CREATE: - key: config/vpp/v2/interfaces/vpp-tap - value: { name:"vpp-tap" type:TAP enabled:true ip_addresses:"192.168.1.1/30" tap: } 2. CREATE: - key: config/linux/interfaces/v2/interface/linux-tap - value: { name:"linux-tap" type:TAP_TO_VPP namespace: host_if_name:"tap" enabled:true ip_addresses:"192.168.1.2/30" tap: } 3. CREATE [DERIVED]: - key: linux/interface/linux-tap/address/static/192.168.1.2/30 - value: 4. CREATE [PROPERTY]: - key: linux/interface/state/linux-tap/UP - value: 5. CREATE [DERIVED]: - key: vpp/interface/vpp-tap/vrf/0/ip-version/v4 - value: 6. CREATE [DERIVED]: - key: vpp/interface/vpp-tap/address/static/192.168.1.1/30 - value: 7. CREATE [DERIVED]: - key: vpp/interface/vpp-tap/has-IP-address - value: x----------------------------------------------------------------------------------------------------------------------x | #2 - NB Transaction took 61.9ms | x----------------------------------------------------------------------------------------------------------------------x +======================================================================================================================+ | #3 - SB Notification | +======================================================================================================================+ * transaction arguments: - seqNum: 3 - type: SB Notification - values: - key: vpp/interface/vpp-tap/link-state/DOWN val: o----------------------------------------------------------------------------------------------------------------------o * executed operations (2020-02-11 19:21:24.323 +0000 UTC -> 2020-02-11 19:21:24.323 +0000 UTC, dur: 0s): 1. CREATE [OBTAINED]: - key: vpp/interface/vpp-tap/link-state/DOWN - value: x----------------------------------------------------------------------------------------------------------------------x | #3 - SB Notification took 300µs | x----------------------------------------------------------------------------------------------------------------------x time="2020-02-11 19:21:24.32356" level=info msg="Transaction 3 successful!" loc="kvscheduler/txn_process.go(402)" logger=kvscheduler time="2020-02-11 19:21:24.32377" level=info msg="Transaction #2 successful! (took 63.2ms)" loc="orchestrator/dispatcher.go(181)" logger=dispatcher time="2020-02-11 19:21:29.86182" level=info msg="Agent plugin state update." lastErr="" loc="statuscheck/plugin_impl_statuscheck.go(183)" logger=status-check plugin=vpp-ifplugin state=ok time="2020-02-11 19:21:29.86212" level=info msg="Transaction 4 successful!" loc="kvscheduler/txn_process.go(402)" logger=kvscheduler +======================================================================================================================+ | #4 - SB Notification | +======================================================================================================================+ * transaction arguments: - seqNum: 4 - type: SB Notification - values: - key: vpp/interface/vpp-tap/link-state/DOWN val: - key: vpp/interface/vpp-tap/link-state/UP val: o----------------------------------------------------------------------------------------------------------------------o * executed operations (2020-02-11 19:21:29.862 +0000 UTC -> 2020-02-11 19:21:29.862 +0000 UTC, dur: 0s): 1. DELETE [WAS-OBTAINED]: - key: vpp/interface/vpp-tap/link-state/DOWN - value: 2. CREATE [OBTAINED]: - key: vpp/interface/vpp-tap/link-state/UP - value: x----------------------------------------------------------------------------------------------------------------------x | #4 - SB Notification took 100µs | x----------------------------------------------------------------------------------------------------------------------x time="2020-02-11 19:21:36.60956" level=error msg="switch to namespace failed:Microservice 'e2e-test-microservice1' is not available" loc="descriptor/interface.go(416)" logger=linux-ifplugin.if-descriptor +======================================================================================================================+ | #5 - SB Notification | +======================================================================================================================+ * transaction arguments: - seqNum: 5 - type: SB Notification - values: - key: linux/microservice/e2e-test-microservice1 val: o----------------------------------------------------------------------------------------------------------------------o * executed operations (2020-02-11 19:21:36.609 +0000 UTC -> 2020-02-11 19:21:36.621 +0000 UTC, dur: 12ms): 1. DELETE [DERIVED]: - key: linux/interface/linux-tap/address/static/192.168.1.2/30 - value: 2. DELETE [PROPERTY]: - key: linux/interface/state/linux-tap/UP - value: 3. DELETE: - key: config/linux/interfaces/v2/interface/linux-tap - value: { name:"linux-tap" type:TAP_TO_VPP namespace: host_if_name:"tap" enabled:true ip_addresses:"192.168.1.2/30" tap: } - error: Microservice 'e2e-test-microservice1' is not available 4. DELETE [DERIVED]: - key: vpp/interface/vpp-tap/has-IP-address - value: 5. DELETE [DERIVED]: - key: vpp/interface/vpp-tap/address/static/192.168.1.1/30 - value: 6. DELETE [DERIVED]: - key: vpp/interface/vpp-tap/vrf/0/ip-version/v4 - value: 7. DELETE [IS-PENDING]: - key: config/vpp/v2/interfaces/vpp-tap - value: { name:"vpp-tap" type:TAP enabled:true ip_addresses:"192.168.1.1/30" tap: } 8. DELETE [WAS-OBTAINED]: - key: linux/microservice/e2e-test-microservice1 - value: x----------------------------------------------------------------------------------------------------------------------x | #5 - SB Notification took 11.7ms | x----------------------------------------------------------------------------------------------------------------------x +======================================================================================================================+ | GRAPH 20 nodes | +======================================================================================================================+ | [linux-interface] config/linux/interfaces/v2/interface/linux-tap (linux-tap) TXN-5 RETRYING | | name: "linux-tap" | | type: TAP_TO_VPP | | namespace: < | | type: MICROSERVICE | | reference: "e2e-test-microservice1" | | > | | host_if_name: "tap" | | enabled: true | | ip_addresses: "192.168.1.2/30" | | tap: < | | vpp_tap_if_name: "vpp-tap" | | > | | Depends on: | | - microservice-available -> linux/microservice/e2e-test-microservice1 | | - vpp-tap-interface-exists -> config/vpp/v2/interfaces/vpp-tap | | Derives: | | - linux/interface/linux-tap/address/static/192.168.1.2/30 | | - linux/interface/state/linux-tap/UP | | Errors: Microservice 'e2e-test-microservice1' is not available | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-nat44-global] config/vpp/nat/v2/nat44-global TXN-0 OBTAINED | | virtual_reassembly: < | | timeout: 2 | | max_reassemblies: 1024 | | max_fragments: 5 | | > | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-interface] config/vpp/v2/interfaces/UNTAGGED-local0 (UNTAGGED-local0) TXN-0 OBTAINED | | name: "UNTAGGED-local0" | | type: SOFTWARE_LOOPBACK | | Metadata: &{SwIfIndex:0 Vrf:0 IPAddresses:[] TAPHostIfName:} | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-interface] config/vpp/v2/interfaces/vpp-tap (vpp-tap) TXN-5 PENDING | | name: "vpp-tap" | | type: TAP | | enabled: true | | ip_addresses: "192.168.1.1/30" | | tap: < | | version: 2 | | to_microservice: "e2e-test-microservice1" | | > | | Depends on: | | - microservice-available -> linux/microservice/e2e-test-microservice1 | | Derives: | | - vpp/interface/vpp-tap/address/static/192.168.1.1/30 | | - vpp/interface/vpp-tap/has-IP-address | | - vpp/interface/vpp-tap/vrf/0/ip-version/v4 | | Dependency for: | | - [linux-interface] config/linux/interfaces/v2/interface/linux-tap | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-ip-scan-neighbor] config/vpp/v2/ipscanneigh-global TXN-0 OBTAINED | | scan_interval: 1 | | max_proc_time: 20 | | max_update: 10 | | scan_int_delay: 1 | | stale_threshold: 4 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-proxy-arp] config/vpp/v2/proxyarp-global TXN-0 OBTAINED | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/0.0.0.0/0/gw/0.0.0.0 TXN-0 OBTAINED | | type: DROP | | dst_network: "0.0.0.0/0" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/0.0.0.0/32/gw/0.0.0.0 TXN-0 OBTAINED | | type: DROP | | dst_network: "0.0.0.0/32" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/224.0.0.0/4/gw/0.0.0.0 TXN-0 OBTAINED | | type: DROP | | dst_network: "224.0.0.0/4" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/240.0.0.0/4/gw/0.0.0.0 TXN-0 OBTAINED | | type: DROP | | dst_network: "240.0.0.0/4" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/255.255.255.255/32/gw/0.0.0.0 TXN-0 OBTAINED | | type: DROP | | dst_network: "255.255.255.255/32" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/::/0/gw/:: TXN-0 OBTAINED | | type: DROP | | dst_network: "::/0" | | next_hop_addr: "::" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/fe80::/10/gw/:: TXN-0 OBTAINED | | dst_network: "fe80::/10" | | next_hop_addr: "::" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-vrf-table] config/vpp/v2/vrf-table/id/0/protocol/IPV4 (id/0/protocol/IPV4) TXN-0 OBTAINED | | label: "ipv4-VRF:0" | | Metadata: &{Index:0 Protocol:IPV4} | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-vrf-table] config/vpp/v2/vrf-table/id/0/protocol/IPV6 (id/0/protocol/IPV6) TXN-0 OBTAINED | | protocol: IPV6 | | label: "ipv6-VRF:0" | | Metadata: &{Index:0 Protocol:IPV6} | +----------------------------------------------------------------------------------------------------------------------+ | [linux-interface-watcher] linux/interface/host-name/eth0 TXN-0 OBTAINED | +----------------------------------------------------------------------------------------------------------------------+ | [linux-interface-watcher] linux/interface/host-name/lo TXN-0 OBTAINED | +----------------------------------------------------------------------------------------------------------------------+ | [microservice] linux/microservice/e2e-test-microservice1 TXN-5 REMOVED | | Dependency for: | | - [linux-interface] config/linux/interfaces/v2/interface/linux-tap | | - [vpp-interface] config/vpp/v2/interfaces/vpp-tap | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-interface-link-state] vpp/interface/UNTAGGED-local0/link-state/DOWN TXN-0 OBTAINED | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-interface-link-state] vpp/interface/vpp-tap/link-state/UP TXN-4 OBTAINED | +======================================================================================================================+ time="2020-02-11 19:21:36.62383" level=error msg="KeyErrors: [config/linux/interfaces/v2/interface/linux-tap (DELETE): Microservice 'e2e-test-microservice1' is not available]" loc="kvscheduler/txn_process.go(404)" logger=kvscheduler +======================================================================================================================+ | #6 - SB Notification | +======================================================================================================================+ * transaction arguments: - seqNum: 6 - type: SB Notification - values: - key: vpp/interface/vpp-tap/link-state/UP val: o----------------------------------------------------------------------------------------------------------------------o * executed operations (2020-02-11 19:21:36.626 +0000 UTC -> 2020-02-11 19:21:36.626 +0000 UTC, dur: 0s): 1. DELETE [WAS-OBTAINED]: - key: vpp/interface/vpp-tap/link-state/UP - value: x----------------------------------------------------------------------------------------------------------------------x | #6 - SB Notification took 300µs | x----------------------------------------------------------------------------------------------------------------------x time="2020-02-11 19:21:36.62695" level=info msg="Transaction 6 successful!" loc="kvscheduler/txn_process.go(402)" logger=kvscheduler +======================================================================================================================+ | #7 - Retry Transaction retrying TX #5 (attempt 1) | +======================================================================================================================+ * transaction arguments: - seqNum: 7 - type: Retry Transaction (for txn 5, attempt #1) - values: - key: config/linux/interfaces/v2/interface/linux-tap val: { name:"linux-tap" type:TAP_TO_VPP namespace: host_if_name:"tap" enabled:true ip_addresses:"192.168.1.2/30" tap: } * planned operations: 1. CREATE [NOOP RETRY IS-PENDING]: - key: config/linux/interfaces/v2/interface/linux-tap - value: { name:"linux-tap" type:TAP_TO_VPP namespace: host_if_name:"tap" enabled:true ip_addresses:"192.168.1.2/30" tap: } - prev-error: Microservice 'e2e-test-microservice1' is not available o----------------------------------------------------------------------------------------------------------------------o * executed operations (2020-02-11 19:21:37.625 +0000 UTC -> 2020-02-11 19:21:37.626 +0000 UTC, dur: 1ms): 1. CREATE [NOOP RETRY IS-PENDING]: - key: config/linux/interfaces/v2/interface/linux-tap - value: { name:"linux-tap" type:TAP_TO_VPP namespace: host_if_name:"tap" enabled:true ip_addresses:"192.168.1.2/30" tap: } - prev-error: Microservice 'e2e-test-microservice1' is not available x----------------------------------------------------------------------------------------------------------------------x | #7 - Retry Transaction took 900µs | x----------------------------------------------------------------------------------------------------------------------x time="2020-02-11 19:21:37.62615" level=info msg="Transaction 7 successful!" loc="kvscheduler/txn_process.go(402)" logger=kvscheduler time="2020-02-11 19:21:42.64214" level=error msg="failed to retrieve values: dumping VPP L3XCs failed: unsupported" descriptor=vpp-l3xc loc="kvscheduler/refresh.go(121)" logger=kvscheduler +======================================================================================================================+ | #8 - NB Transaction DownstreamResync | +======================================================================================================================+ * transaction arguments: - seqNum: 8 - type: NB Transaction, SB Sync o----------------------------------------------------------------------------------------------------------------------o * executed operations (2020-02-11 19:21:42.637 +0000 UTC -> 2020-02-11 19:21:42.646 +0000 UTC, dur: 9ms): 1. CREATE [NOOP STILL-PENDING]: - key: config/linux/interfaces/v2/interface/linux-tap - value: { name:"linux-tap" type:TAP_TO_VPP namespace: host_if_name:"tap" enabled:true ip_addresses:"192.168.1.2/30" tap: } 2. CREATE [NOOP STILL-PENDING]: - key: config/vpp/v2/interfaces/vpp-tap - value: { name:"vpp-tap" type:TAP enabled:true ip_addresses:"192.168.1.1/30" tap: } x----------------------------------------------------------------------------------------------------------------------x | #8 - NB Transaction took 9.1ms | x----------------------------------------------------------------------------------------------------------------------x +======================================================================================================================+ | #9 - SB Notification | +======================================================================================================================+ * transaction arguments: - seqNum: 9 - type: SB Notification - values: - key: linux/microservice/e2e-test-microservice1 val: o----------------------------------------------------------------------------------------------------------------------o * executed operations (2020-02-11 19:21:42.964 +0000 UTC -> 2020-02-11 19:21:43.014 +0000 UTC, dur: 50ms): 1. CREATE [OBTAINED]: - key: linux/microservice/e2e-test-microservice1 - value: 2. CREATE [WAS-PENDING]: - key: config/vpp/v2/interfaces/vpp-tap - value: { name:"vpp-tap" type:TAP enabled:true ip_addresses:"192.168.1.1/30" tap: } 3. CREATE [WAS-PENDING]: - key: config/linux/interfaces/v2/interface/linux-tap - value: { name:"linux-tap" type:TAP_TO_VPP namespace: host_if_name:"tap" enabled:true ip_addresses:"192.168.1.2/30" tap: } 4. CREATE [DERIVED]: - key: linux/interface/linux-tap/address/static/192.168.1.2/30 - value: 5. CREATE [PROPERTY]: - key: linux/interface/state/linux-tap/UP - value: 6. CREATE [DERIVED]: - key: vpp/interface/vpp-tap/vrf/0/ip-version/v4 - value: 7. CREATE [DERIVED]: - key: vpp/interface/vpp-tap/address/static/192.168.1.1/30 - value: 8. CREATE [DERIVED]: - key: vpp/interface/vpp-tap/has-IP-address - value: x----------------------------------------------------------------------------------------------------------------------x | #9 - SB Notification took 50.4ms | x----------------------------------------------------------------------------------------------------------------------x time="2020-02-11 19:21:43.01466" level=info msg="Transaction 9 successful!" loc="kvscheduler/txn_process.go(402)" logger=kvscheduler +======================================================================================================================+ | #10 - SB Notification | +======================================================================================================================+ * transaction arguments: - seqNum: 10 - type: SB Notification - values: - key: vpp/interface/vpp-tap/link-state/DOWN val: o----------------------------------------------------------------------------------------------------------------------o * executed operations (2020-02-11 19:21:43.015 +0000 UTC -> 2020-02-11 19:21:43.017 +0000 UTC, dur: 1ms): 1. CREATE [OBTAINED]: - key: vpp/interface/vpp-tap/link-state/DOWN - value: x----------------------------------------------------------------------------------------------------------------------x | #10 - SB Notification took 1.2ms | x----------------------------------------------------------------------------------------------------------------------x time="2020-02-11 19:21:43.01693" level=info msg="Transaction 10 successful!" loc="kvscheduler/txn_process.go(402)" logger=kvscheduler +======================================================================================================================+ | #11 - SB Notification | +======================================================================================================================+ * transaction arguments: - seqNum: 11 - type: SB Notification - values: - key: vpp/interface/vpp-tap/link-state/DOWN val: - key: vpp/interface/vpp-tap/link-state/UP val: o----------------------------------------------------------------------------------------------------------------------o * executed operations (2020-02-11 19:21:47.862 +0000 UTC -> 2020-02-11 19:21:47.862 +0000 UTC, dur: 0s): 1. DELETE [WAS-OBTAINED]: - key: vpp/interface/vpp-tap/link-state/DOWN - value: 2. CREATE [OBTAINED]: - key: vpp/interface/vpp-tap/link-state/UP - value: x----------------------------------------------------------------------------------------------------------------------x | #11 - SB Notification took 500µs | x----------------------------------------------------------------------------------------------------------------------x time="2020-02-11 19:21:47.86313" level=info msg="Transaction 11 successful!" loc="kvscheduler/txn_process.go(402)" logger=kvscheduler time="2020-02-11 19:21:52.12927" level=error msg="failed to retrieve values: dumping VPP L3XCs failed: unsupported" descriptor=vpp-l3xc loc="kvscheduler/refresh.go(121)" logger=kvscheduler +======================================================================================================================+ | #12 - NB Transaction DownstreamResync | +======================================================================================================================+ * transaction arguments: - seqNum: 12 - type: NB Transaction, SB Sync o----------------------------------------------------------------------------------------------------------------------o * executed operations: x----------------------------------------------------------------------------------------------------------------------x | #12 - NB Transaction took 45ms | x----------------------------------------------------------------------------------------------------------------------x +======================================================================================================================+ | #13 - SB Notification | +======================================================================================================================+ * transaction arguments: - seqNum: 13 - type: SB Notification - values: - key: linux/microservice/e2e-test-microservice1 val: time="2020-02-11 19:21:55.33421" level=error msg="switch to namespace failed:Microservice 'e2e-test-microservice1' is not available" loc="descriptor/interface.go(416)" logger=linux-ifplugin.if-descriptor o----------------------------------------------------------------------------------------------------------------------o * executed operations (2020-02-11 19:21:55.334 +0000 UTC -> 2020-02-11 19:21:55.349 +0000 UTC, dur: 15ms): 1. DELETE [DERIVED]: - key: linux/interface/linux-tap/address/static/192.168.1.2/30 - value: 2. DELETE [PROPERTY]: - key: linux/interface/state/linux-tap/UP - value: 3. DELETE: - key: config/linux/interfaces/v2/interface/linux-tap - value: { name:"linux-tap" type:TAP_TO_VPP namespace: host_if_name:"tap" enabled:true ip_addresses:"192.168.1.2/30" tap: } - error: Microservice 'e2e-test-microservice1' is not available 4. DELETE [DERIVED]: - key: vpp/interface/vpp-tap/has-IP-address - value: 5. DELETE [DERIVED]: - key: vpp/interface/vpp-tap/address/static/192.168.1.1/30 - value: 6. DELETE [DERIVED]: - key: vpp/interface/vpp-tap/vrf/0/ip-version/v4 - value: 7. DELETE [IS-PENDING]: - key: config/vpp/v2/interfaces/vpp-tap - value: { name:"vpp-tap" type:TAP enabled:true ip_addresses:"192.168.1.1/30" tap: } 8. DELETE [WAS-OBTAINED]: - key: linux/microservice/e2e-test-microservice1 - value: x----------------------------------------------------------------------------------------------------------------------x | #13 - SB Notification took 15.1ms | x----------------------------------------------------------------------------------------------------------------------x time="2020-02-11 19:21:55.35101" level=error msg="KeyErrors: [config/linux/interfaces/v2/interface/linux-tap (DELETE): Microservice 'e2e-test-microservice1' is not available]" loc="kvscheduler/txn_process.go(404)" logger=kvscheduler +======================================================================================================================+ | GRAPH 29 nodes | +======================================================================================================================+ | [linux-interface] config/linux/interfaces/v2/interface/linux-tap (linux-tap) TXN-13 RETRYING | | name: "linux-tap" | | type: TAP_TO_VPP | | namespace: < | | type: MICROSERVICE | | reference: "e2e-test-microservice1" | | > | | host_if_name: "tap" | | enabled: true | | ip_addresses: "192.168.1.2/30" | | tap: < | | vpp_tap_if_name: "vpp-tap" | | > | | Depends on: | | - microservice-available -> linux/microservice/e2e-test-microservice1 | | - vpp-tap-interface-exists -> config/vpp/v2/interfaces/vpp-tap | | Derives: | | - linux/interface/linux-tap/address/static/192.168.1.2/30 | | - linux/interface/state/linux-tap/UP | | Errors: Microservice 'e2e-test-microservice1' is not available | +----------------------------------------------------------------------------------------------------------------------+ | [linux-arp] config/linux/l3/v2/arp/linux-tap/192.168.1.1 (linux-tap/192.168.1.1) TXN-12 OBTAINED | | interface: "linux-tap" | | ip_address: "192.168.1.1" | | hw_address: "02:fe:2d:63:d2:aa" | | Depends on: | | - interface-has-ip-address -> | | - interface-is-up -> | +----------------------------------------------------------------------------------------------------------------------+ | [linux-route] config/linux/l3/v2/route/192.168.1.0/30/linux-tap (192.168.1.0/30/linux-tap) TXN-12 OBTAINED | | outgoing_interface: "linux-tap" | | scope: LINK | | dst_network: "192.168.1.0/30" | | Depends on: | | - outgoing-interface-has-ip-address -> | | - outgoing-interface-is-up -> | | Derives: | | - linux/link-local-route/linux-tap/dest-address/192.168.1.0/30 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-nat44-global] config/vpp/nat/v2/nat44-global TXN-12 OBTAINED | | virtual_reassembly: < | | timeout: 2 | | max_reassemblies: 1024 | | max_fragments: 5 | | > | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-arp] config/vpp/v2/arp/vpp-tap/192.168.1.2 (vpp-tap/192.168.1.2) TXN-12 OBTAINED | | interface: "vpp-tap" | | ip_address: "192.168.1.2" | | phys_address: "3e:f6:41:c1:eb:63" | | Depends on: | | - interface-exists -> config/vpp/v2/interfaces/vpp-tap | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-interface] config/vpp/v2/interfaces/UNTAGGED-local0 (UNTAGGED-local0) TXN-12 OBTAINED | | name: "UNTAGGED-local0" | | type: SOFTWARE_LOOPBACK | | Metadata: &{SwIfIndex:0 Vrf:0 IPAddresses:[] TAPHostIfName:} | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-interface] config/vpp/v2/interfaces/vpp-tap (vpp-tap) TXN-13 PENDING | | name: "vpp-tap" | | type: TAP | | enabled: true | | ip_addresses: "192.168.1.1/30" | | tap: < | | version: 2 | | to_microservice: "e2e-test-microservice1" | | > | | Depends on: | | - microservice-available -> linux/microservice/e2e-test-microservice1 | | Derives: | | - vpp/interface/vpp-tap/address/static/192.168.1.1/30 | | - vpp/interface/vpp-tap/has-IP-address | | - vpp/interface/vpp-tap/vrf/0/ip-version/v4 | | Dependency for: | | - [vpp-arp] config/vpp/v2/arp/vpp-tap/192.168.1.2 | | - [vpp-route] config/vpp/v2/route/if/vpp-tap/vrf/0/dst/192.168.1.0/30/gw/0.0.0.0 | | - [vpp-route] config/vpp/v2/route/if/vpp-tap/vrf/0/dst/192.168.1.1/32/gw/192.168.1.1 | | - [vpp-route] config/vpp/v2/route/if/vpp-tap/vrf/0/dst/192.168.1.2/32/gw/192.168.1.2 | | - [linux-interface] config/linux/interfaces/v2/interface/linux-tap | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-ip-scan-neighbor] config/vpp/v2/ipscanneigh-global TXN-12 OBTAINED | | scan_interval: 1 | | max_proc_time: 20 | | max_update: 10 | | scan_int_delay: 1 | | stale_threshold: 4 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-proxy-arp] config/vpp/v2/proxyarp-global TXN-12 OBTAINED | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/if/vpp-tap/vrf/0/dst/192.168.1.0/30/gw/0.0.0.0 TXN-12 OBTAINED | | dst_network: "192.168.1.1/30" | | next_hop_addr: "0.0.0.0" | | outgoing_interface: "vpp-tap" | | weight: 1 | | Depends on: | | - interface-exists -> config/vpp/v2/interfaces/vpp-tap | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/if/vpp-tap/vrf/0/dst/192.168.1.1/32/gw/192.168.1.1 TXN-12 OBTAINED | | dst_network: "192.168.1.1/32" | | next_hop_addr: "192.168.1.1" | | outgoing_interface: "vpp-tap" | | weight: 1 | | Depends on: | | - interface-exists -> config/vpp/v2/interfaces/vpp-tap | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/if/vpp-tap/vrf/0/dst/192.168.1.2/32/gw/192.168.1.2 TXN-12 OBTAINED | | dst_network: "192.168.1.2/32" | | next_hop_addr: "192.168.1.2" | | outgoing_interface: "vpp-tap" | | weight: 1 | | Depends on: | | - interface-exists -> config/vpp/v2/interfaces/vpp-tap | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/0.0.0.0/0/gw/0.0.0.0 TXN-12 OBTAINED | | type: DROP | | dst_network: "0.0.0.0/0" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/0.0.0.0/32/gw/0.0.0.0 TXN-12 OBTAINED | | type: DROP | | dst_network: "0.0.0.0/32" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/192.168.1.0/32/gw/0.0.0.0 TXN-12 OBTAINED | | type: DROP | | dst_network: "192.168.1.0/32" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/192.168.1.3/32/gw/0.0.0.0 TXN-12 OBTAINED | | type: DROP | | dst_network: "192.168.1.3/32" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/224.0.0.0/4/gw/0.0.0.0 TXN-12 OBTAINED | | type: DROP | | dst_network: "224.0.0.0/4" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/240.0.0.0/4/gw/0.0.0.0 TXN-12 OBTAINED | | type: DROP | | dst_network: "240.0.0.0/4" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/255.255.255.255/32/gw/0.0.0.0 TXN-12 OBTAINED | | type: DROP | | dst_network: "255.255.255.255/32" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/::/0/gw/:: TXN-12 OBTAINED | | type: DROP | | dst_network: "::/0" | | next_hop_addr: "::" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/fe80::/10/gw/:: TXN-12 OBTAINED | | dst_network: "fe80::/10" | | next_hop_addr: "::" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-vrf-table] config/vpp/v2/vrf-table/id/0/protocol/IPV4 (id/0/protocol/IPV4) TXN-12 OBTAINED | | label: "ipv4-VRF:0" | | Metadata: &{Index:0 Protocol:IPV4} | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-vrf-table] config/vpp/v2/vrf-table/id/0/protocol/IPV6 (id/0/protocol/IPV6) TXN-12 OBTAINED | | protocol: IPV6 | | label: "ipv6-VRF:0" | | Metadata: &{Index:0 Protocol:IPV6} | +----------------------------------------------------------------------------------------------------------------------+ | [linux-interface-watcher] linux/interface/host-name/eth0 TXN-12 OBTAINED | +----------------------------------------------------------------------------------------------------------------------+ | [linux-interface-watcher] linux/interface/host-name/lo TXN-12 OBTAINED | +----------------------------------------------------------------------------------------------------------------------+ | linux/link-local-route/linux-tap/dest-address/192.168.1.0/30 TXN-12 OBTAINED | | Derived from: config/linux/l3/v2/route/192.168.1.0/30/linux-tap | +----------------------------------------------------------------------------------------------------------------------+ | [microservice] linux/microservice/e2e-test-microservice1 TXN-13 REMOVED | | Dependency for: | | - [linux-interface] config/linux/interfaces/v2/interface/linux-tap | | - [vpp-interface] config/vpp/v2/interfaces/vpp-tap | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-interface-link-state] vpp/interface/UNTAGGED-local0/link-state/DOWN TXN-12 OBTAINED | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-interface-link-state] vpp/interface/vpp-tap/link-state/UP TXN-12 OBTAINED | +======================================================================================================================+ +======================================================================================================================+ | #14 - SB Notification | +======================================================================================================================+ * transaction arguments: - seqNum: 14 - type: SB Notification - values: - key: vpp/interface/vpp-tap/link-state/UP val: o----------------------------------------------------------------------------------------------------------------------o * executed operations (2020-02-11 19:21:55.351 +0000 UTC -> 2020-02-11 19:21:55.351 +0000 UTC, dur: 0s): 1. DELETE [WAS-OBTAINED]: - key: vpp/interface/vpp-tap/link-state/UP - value: x----------------------------------------------------------------------------------------------------------------------x | #14 - SB Notification took 100µs | x----------------------------------------------------------------------------------------------------------------------x time="2020-02-11 19:21:55.35159" level=info msg="Transaction 14 successful!" loc="kvscheduler/txn_process.go(402)" logger=kvscheduler +======================================================================================================================+ | #15 - Retry Transaction retrying TX #13 (attempt 1) | +======================================================================================================================+ * transaction arguments: - seqNum: 15 - type: Retry Transaction (for txn 13, attempt #1) - values: - key: config/linux/interfaces/v2/interface/linux-tap val: { name:"linux-tap" type:TAP_TO_VPP namespace: host_if_name:"tap" enabled:true ip_addresses:"192.168.1.2/30" tap: } * planned operations: 1. CREATE [NOOP RETRY IS-PENDING]: - key: config/linux/interfaces/v2/interface/linux-tap - value: { name:"linux-tap" type:TAP_TO_VPP namespace: host_if_name:"tap" enabled:true ip_addresses:"192.168.1.2/30" tap: } - prev-error: Microservice 'e2e-test-microservice1' is not available o----------------------------------------------------------------------------------------------------------------------o * executed operations (2020-02-11 19:21:56.351 +0000 UTC -> 2020-02-11 19:21:56.351 +0000 UTC, dur: 0s): 1. CREATE [NOOP RETRY IS-PENDING]: - key: config/linux/interfaces/v2/interface/linux-tap - value: { name:"linux-tap" type:TAP_TO_VPP namespace: host_if_name:"tap" enabled:true ip_addresses:"192.168.1.2/30" tap: } - prev-error: Microservice 'e2e-test-microservice1' is not available x----------------------------------------------------------------------------------------------------------------------x | #15 - Retry Transaction took 300µs | x----------------------------------------------------------------------------------------------------------------------x time="2020-02-11 19:21:56.35180" level=info msg="Transaction 15 successful!" loc="kvscheduler/txn_process.go(402)" logger=kvscheduler time="2020-02-11 19:22:01.37004" level=error msg="failed to retrieve values: dumping VPP L3XCs failed: unsupported" descriptor=vpp-l3xc loc="kvscheduler/refresh.go(121)" logger=kvscheduler +======================================================================================================================+ | #16 - NB Transaction DownstreamResync | +======================================================================================================================+ * transaction arguments: - seqNum: 16 - type: NB Transaction, SB Sync o----------------------------------------------------------------------------------------------------------------------o * executed operations (2020-02-11 19:22:01.365 +0000 UTC -> 2020-02-11 19:22:01.374 +0000 UTC, dur: 10ms): 1. CREATE [NOOP STILL-PENDING]: - key: config/linux/interfaces/v2/interface/linux-tap - value: { name:"linux-tap" type:TAP_TO_VPP namespace: host_if_name:"tap" enabled:true ip_addresses:"192.168.1.2/30" tap: } 2. CREATE [NOOP STILL-PENDING]: - key: config/vpp/v2/interfaces/vpp-tap - value: { name:"vpp-tap" type:TAP enabled:true ip_addresses:"192.168.1.1/30" tap: } x----------------------------------------------------------------------------------------------------------------------x | #16 - NB Transaction took 9.5ms | x----------------------------------------------------------------------------------------------------------------------x +======================================================================================================================+ | #17 - SB Notification | +======================================================================================================================+ * transaction arguments: - seqNum: 17 - type: SB Notification - values: - key: linux/microservice/e2e-test-microservice1 val: o----------------------------------------------------------------------------------------------------------------------o * executed operations (2020-02-11 19:22:01.683 +0000 UTC -> 2020-02-11 19:22:01.73 +0000 UTC, dur: 47ms): 1. CREATE [OBTAINED]: - key: linux/microservice/e2e-test-microservice1 - value: 2. CREATE [WAS-PENDING]: - key: config/vpp/v2/interfaces/vpp-tap - value: { name:"vpp-tap" type:TAP enabled:true ip_addresses:"192.168.1.1/30" tap: } 3. CREATE [WAS-PENDING]: - key: config/linux/interfaces/v2/interface/linux-tap - value: { name:"linux-tap" type:TAP_TO_VPP namespace: host_if_name:"tap" enabled:true ip_addresses:"192.168.1.2/30" tap: } 4. CREATE [DERIVED]: - key: linux/interface/linux-tap/address/static/192.168.1.2/30 - value: 5. CREATE [PROPERTY]: - key: linux/interface/state/linux-tap/UP - value: 6. CREATE [DERIVED]: - key: vpp/interface/vpp-tap/vrf/0/ip-version/v4 - value: 7. CREATE [DERIVED]: - key: vpp/interface/vpp-tap/address/static/192.168.1.1/30 - value: 8. CREATE [DERIVED]: - key: vpp/interface/vpp-tap/has-IP-address - value: x----------------------------------------------------------------------------------------------------------------------x | #17 - SB Notification took 47.4ms | x----------------------------------------------------------------------------------------------------------------------x time="2020-02-11 19:22:01.73092" level=info msg="Transaction 17 successful!" loc="kvscheduler/txn_process.go(402)" logger=kvscheduler +======================================================================================================================+ | #18 - SB Notification | +======================================================================================================================+ * transaction arguments: - seqNum: 18 - type: SB Notification - values: - key: vpp/interface/vpp-tap/link-state/DOWN val: o----------------------------------------------------------------------------------------------------------------------o * executed operations (2020-02-11 19:22:01.732 +0000 UTC -> 2020-02-11 19:22:01.733 +0000 UTC, dur: 1ms): 1. CREATE [OBTAINED]: - key: vpp/interface/vpp-tap/link-state/DOWN - value: x----------------------------------------------------------------------------------------------------------------------x | #18 - SB Notification took 1ms | x----------------------------------------------------------------------------------------------------------------------x time="2020-02-11 19:22:01.73331" level=info msg="Transaction 18 successful!" loc="kvscheduler/txn_process.go(402)" logger=kvscheduler +======================================================================================================================+ | #19 - SB Notification | +======================================================================================================================+ * transaction arguments: - seqNum: 19 - type: SB Notification - values: - key: vpp/interface/vpp-tap/link-state/DOWN val: - key: vpp/interface/vpp-tap/link-state/UP val: o----------------------------------------------------------------------------------------------------------------------o * executed operations (2020-02-11 19:22:05.862 +0000 UTC -> 2020-02-11 19:22:05.862 +0000 UTC, dur: 0s): 1. DELETE [WAS-OBTAINED]: - key: vpp/interface/vpp-tap/link-state/DOWN - value: 2. CREATE [OBTAINED]: - key: vpp/interface/vpp-tap/link-state/UP - value: x----------------------------------------------------------------------------------------------------------------------x | #19 - SB Notification took 500µs | x----------------------------------------------------------------------------------------------------------------------x time="2020-02-11 19:22:05.86313" level=info msg="Transaction 19 successful!" loc="kvscheduler/txn_process.go(402)" logger=kvscheduler time="2020-02-11 19:22:10.83116" level=error msg="failed to retrieve values: dumping VPP L3XCs failed: unsupported" descriptor=vpp-l3xc loc="kvscheduler/refresh.go(121)" logger=kvscheduler +======================================================================================================================+ | #20 - NB Transaction DownstreamResync | +======================================================================================================================+ * transaction arguments: - seqNum: 20 - type: NB Transaction, SB Sync o----------------------------------------------------------------------------------------------------------------------o * executed operations: x----------------------------------------------------------------------------------------------------------------------x | #20 - NB Transaction took 31.6ms | x----------------------------------------------------------------------------------------------------------------------x +======================================================================================================================+ | #21 - NB Transaction | +======================================================================================================================+ * transaction arguments: - seqNum: 21 - type: NB Transaction - values: - key: config/vpp/v2/interfaces/vpp-tap val: o----------------------------------------------------------------------------------------------------------------------o * executed operations (2020-02-11 19:22:10.842 +0000 UTC -> 2020-02-11 19:22:10.909 +0000 UTC, dur: 67ms): 1. DELETE [DERIVED]: - key: vpp/interface/vpp-tap/has-IP-address - value: 2. DELETE [DERIVED]: - key: vpp/interface/vpp-tap/address/static/192.168.1.1/30 - value: 3. DELETE [DERIVED]: - key: vpp/interface/vpp-tap/vrf/0/ip-version/v4 - value: 4. DELETE [DERIVED]: - key: linux/interface/linux-tap/address/static/192.168.1.2/30 - value: 5. DELETE [PROPERTY]: - key: linux/interface/state/linux-tap/UP - value: 6. DELETE [IS-PENDING]: - key: config/linux/interfaces/v2/interface/linux-tap - value: { name:"linux-tap" type:TAP_TO_VPP namespace: host_if_name:"tap" enabled:true ip_addresses:"192.168.1.2/30" tap: } 7. DELETE: - key: config/vpp/v2/interfaces/vpp-tap - value: { name:"vpp-tap" type:TAP enabled:true ip_addresses:"192.168.1.1/30" tap: } x----------------------------------------------------------------------------------------------------------------------x | #21 - NB Transaction took 67.2ms | x----------------------------------------------------------------------------------------------------------------------x time="2020-02-11 19:22:10.90972" level=info msg="Transaction #21 successful! (took 67.8ms)" loc="orchestrator/dispatcher.go(181)" logger=dispatcher +======================================================================================================================+ | #22 - SB Notification | +======================================================================================================================+ * transaction arguments: - seqNum: 22 - type: SB Notification - values: - key: vpp/interface/vpp-tap/link-state/UP val: o----------------------------------------------------------------------------------------------------------------------o * executed operations (2020-02-11 19:22:10.91 +0000 UTC -> 2020-02-11 19:22:10.911 +0000 UTC, dur: 1ms): 1. DELETE [WAS-OBTAINED]: - key: vpp/interface/vpp-tap/link-state/UP - value: x----------------------------------------------------------------------------------------------------------------------x | #22 - SB Notification took 1.3ms | x----------------------------------------------------------------------------------------------------------------------x time="2020-02-11 19:22:10.91106" level=info msg="Transaction 22 successful!" loc="kvscheduler/txn_process.go(402)" logger=kvscheduler +======================================================================================================================+ | #23 - NB Transaction | +======================================================================================================================+ * transaction arguments: - seqNum: 23 - type: NB Transaction - values: - key: config/vpp/v2/interfaces/vpp-tap val: { name:"vpp-tap" type:TAP enabled:true ip_addresses:"192.168.1.1/30" tap: } o----------------------------------------------------------------------------------------------------------------------o * executed operations (2020-02-11 19:22:15.973 +0000 UTC -> 2020-02-11 19:22:16.018 +0000 UTC, dur: 45ms): 1. CREATE: - key: config/vpp/v2/interfaces/vpp-tap - value: { name:"vpp-tap" type:TAP enabled:true ip_addresses:"192.168.1.1/30" tap: } 2. CREATE [WAS-PENDING]: - key: config/linux/interfaces/v2/interface/linux-tap - value: { name:"linux-tap" type:TAP_TO_VPP namespace: host_if_name:"tap" enabled:true ip_addresses:"192.168.1.2/30" tap: } 3. CREATE [DERIVED]: - key: linux/interface/linux-tap/address/static/192.168.1.2/30 - value: 4. CREATE [PROPERTY]: - key: linux/interface/state/linux-tap/UP - value: 5. CREATE [DERIVED]: - key: vpp/interface/vpp-tap/vrf/0/ip-version/v4 - value: 6. CREATE [DERIVED]: - key: vpp/interface/vpp-tap/address/static/192.168.1.1/30 - value: 7. CREATE [DERIVED]: - key: vpp/interface/vpp-tap/has-IP-address - value: x----------------------------------------------------------------------------------------------------------------------x | #23 - NB Transaction took 44.8ms | x----------------------------------------------------------------------------------------------------------------------x +======================================================================================================================+ | #24 - SB Notification | +======================================================================================================================+ * transaction arguments: - seqNum: 24 - type: SB Notification - values: - key: vpp/interface/vpp-tap/link-state/DOWN val: o----------------------------------------------------------------------------------------------------------------------o * executed operations (2020-02-11 19:22:16.019 +0000 UTC -> 2020-02-11 19:22:16.02 +0000 UTC, dur: 0s): 1. CREATE [OBTAINED]: - key: vpp/interface/vpp-tap/link-state/DOWN - value: x----------------------------------------------------------------------------------------------------------------------x | #24 - SB Notification took 300µs | x----------------------------------------------------------------------------------------------------------------------x time="2020-02-11 19:22:16.02024" level=info msg="Transaction 24 successful!" loc="kvscheduler/txn_process.go(402)" logger=kvscheduler time="2020-02-11 19:22:16.02051" level=info msg="Transaction #23 successful! (took 46.9ms)" loc="orchestrator/dispatcher.go(181)" logger=dispatcher +======================================================================================================================+ | #25 - SB Notification | +======================================================================================================================+ * transaction arguments: - seqNum: 25 - type: SB Notification - values: - key: vpp/interface/vpp-tap/link-state/DOWN val: - key: vpp/interface/vpp-tap/link-state/UP val: o----------------------------------------------------------------------------------------------------------------------o * executed operations (2020-02-11 19:22:20.862 +0000 UTC -> 2020-02-11 19:22:20.862 +0000 UTC, dur: 0s): 1. DELETE [WAS-OBTAINED]: - key: vpp/interface/vpp-tap/link-state/DOWN - value: 2. CREATE [OBTAINED]: - key: vpp/interface/vpp-tap/link-state/UP - value: x----------------------------------------------------------------------------------------------------------------------x | #25 - SB Notification took 500µs | x----------------------------------------------------------------------------------------------------------------------x time="2020-02-11 19:22:20.86316" level=info msg="Transaction 25 successful!" loc="kvscheduler/txn_process.go(402)" logger=kvscheduler time="2020-02-11 19:22:25.13299" level=error msg="failed to retrieve values: dumping VPP L3XCs failed: unsupported" descriptor=vpp-l3xc loc="kvscheduler/refresh.go(121)" logger=kvscheduler +======================================================================================================================+ | #26 - NB Transaction DownstreamResync | +======================================================================================================================+ * transaction arguments: - seqNum: 26 - type: NB Transaction, SB Sync o----------------------------------------------------------------------------------------------------------------------o * executed operations: x----------------------------------------------------------------------------------------------------------------------x | #26 - NB Transaction took 40.7ms | x----------------------------------------------------------------------------------------------------------------------x +======================================================================================================================+ | #27 - NB Transaction | +======================================================================================================================+ * transaction arguments: - seqNum: 27 - type: NB Transaction - values: - key: config/linux/interfaces/v2/interface/linux-tap val: o----------------------------------------------------------------------------------------------------------------------o * executed operations (2020-02-11 19:22:25.145 +0000 UTC -> 2020-02-11 19:22:25.182 +0000 UTC, dur: 37ms): 1. DELETE [DERIVED]: - key: linux/interface/linux-tap/address/static/192.168.1.2/30 - value: 2. DELETE [PROPERTY]: - key: linux/interface/state/linux-tap/UP - value: 3. DELETE: - key: config/linux/interfaces/v2/interface/linux-tap - value: { name:"linux-tap" type:TAP_TO_VPP namespace: host_if_name:"tap" enabled:true ip_addresses:"192.168.1.2/30" tap: } x----------------------------------------------------------------------------------------------------------------------x | #27 - NB Transaction took 37ms | x----------------------------------------------------------------------------------------------------------------------x time="2020-02-11 19:22:25.18317" level=info msg="Transaction #27 successful! (took 37.6ms)" loc="orchestrator/dispatcher.go(181)" logger=dispatcher +======================================================================================================================+ | #28 - SB Notification | +======================================================================================================================+ * transaction arguments: - seqNum: 28 - type: SB Notification - values: - key: linux/interface/host-name/tap-2870264825 val: o----------------------------------------------------------------------------------------------------------------------o * executed operations (2020-02-11 19:22:25.682 +0000 UTC -> 2020-02-11 19:22:25.682 +0000 UTC, dur: 1ms): 1. CREATE [OBTAINED]: - key: linux/interface/host-name/tap-2870264825 - value: x----------------------------------------------------------------------------------------------------------------------x | #28 - SB Notification took 700µs | x----------------------------------------------------------------------------------------------------------------------x time="2020-02-11 19:22:25.68342" level=info msg="Transaction 28 successful!" loc="kvscheduler/txn_process.go(402)" logger=kvscheduler +======================================================================================================================+ | #29 - NB Transaction | +======================================================================================================================+ * transaction arguments: - seqNum: 29 - type: NB Transaction - values: - key: config/linux/interfaces/v2/interface/linux-tap val: { name:"linux-tap" type:TAP_TO_VPP namespace: host_if_name:"tap" enabled:true ip_addresses:"192.168.1.2/30" tap: } o----------------------------------------------------------------------------------------------------------------------o * executed operations (2020-02-11 19:22:30.265 +0000 UTC -> 2020-02-11 19:22:30.266 +0000 UTC, dur: 1ms): 1. CREATE: - key: config/linux/interfaces/v2/interface/linux-tap - value: { name:"linux-tap" type:TAP_TO_VPP namespace: host_if_name:"tap" enabled:true ip_addresses:"192.168.1.2/30" tap: } - error: LinkByName "ta\x04": Link not found x----------------------------------------------------------------------------------------------------------------------x | #29 - NB Transaction took 700µs | x----------------------------------------------------------------------------------------------------------------------x +======================================================================================================================+ | GRAPH 33 nodes | +======================================================================================================================+ | [linux-interface] config/linux/interfaces/v2/interface/linux-tap (linux-tap) TXN-29 RETRYING | | name: "linux-tap" | | type: TAP_TO_VPP | | namespace: < | | type: MICROSERVICE | | reference: "e2e-test-microservice1" | | > | | host_if_name: "tap" | | enabled: true | | ip_addresses: "192.168.1.2/30" | | tap: < | | vpp_tap_if_name: "vpp-tap" | | > | | Depends on: | | - microservice-available -> linux/microservice/e2e-test-microservice1 | | - vpp-tap-interface-exists -> config/vpp/v2/interfaces/vpp-tap | | Derives: | | - linux/interface/linux-tap/address/static/192.168.1.2/30 | | - linux/interface/state/linux-tap/UP | | Errors: LinkByName "ta\x04": Link not found | +----------------------------------------------------------------------------------------------------------------------+ | [linux-arp] config/linux/l3/v2/arp/linux-tap/192.168.1.1 (linux-tap/192.168.1.1) TXN-26 OBTAINED | | interface: "linux-tap" | | ip_address: "192.168.1.1" | | hw_address: "02:fe:33:f1:dd:79" | | Depends on: | | - interface-has-ip-address -> | | - interface-is-up -> | +----------------------------------------------------------------------------------------------------------------------+ | [linux-route] config/linux/l3/v2/route/192.168.1.0/30/linux-tap (192.168.1.0/30/linux-tap) TXN-26 OBTAINED | | outgoing_interface: "linux-tap" | | scope: LINK | | dst_network: "192.168.1.0/30" | | Depends on: | | - outgoing-interface-has-ip-address -> | | - outgoing-interface-is-up -> | | Derives: | | - linux/link-local-route/linux-tap/dest-address/192.168.1.0/30 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-nat44-global] config/vpp/nat/v2/nat44-global TXN-26 OBTAINED | | virtual_reassembly: < | | timeout: 2 | | max_reassemblies: 1024 | | max_fragments: 5 | | > | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-arp] config/vpp/v2/arp/vpp-tap/192.168.1.2 (vpp-tap/192.168.1.2) TXN-26 OBTAINED | | interface: "vpp-tap" | | ip_address: "192.168.1.2" | | phys_address: "76:46:90:94:98:b5" | | Depends on: | | - interface-exists -> config/vpp/v2/interfaces/vpp-tap | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-interface] config/vpp/v2/interfaces/UNTAGGED-local0 (UNTAGGED-local0) TXN-26 OBTAINED | | name: "UNTAGGED-local0" | | type: SOFTWARE_LOOPBACK | | Metadata: &{SwIfIndex:0 Vrf:0 IPAddresses:[] TAPHostIfName:} | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-interface] config/vpp/v2/interfaces/vpp-tap (vpp-tap) TXN-26 CONFIGURED | | name: "vpp-tap" | | type: TAP | | enabled: true | | ip_addresses: "192.168.1.1/30" | | tap: < | | version: 2 | | to_microservice: "e2e-test-microservice1" | | > | | Depends on: | | - microservice-available -> linux/microservice/e2e-test-microservice1 | | Derives: | | - [vpp-interface-address] vpp/interface/vpp-tap/address/static/192.168.1.1/30 | | - [vpp-interface-has-address] vpp/interface/vpp-tap/has-IP-address | | - [vpp-interface-vrf] vpp/interface/vpp-tap/vrf/0/ip-version/v4 | | Dependency for: | | - [vpp-arp] config/vpp/v2/arp/vpp-tap/192.168.1.2 | | - [vpp-route] config/vpp/v2/route/if/vpp-tap/vrf/0/dst/192.168.1.0/30/gw/0.0.0.0 | | - [vpp-route] config/vpp/v2/route/if/vpp-tap/vrf/0/dst/192.168.1.1/32/gw/192.168.1.1 | | - [vpp-route] config/vpp/v2/route/if/vpp-tap/vrf/0/dst/192.168.1.2/32/gw/192.168.1.2 | | - [linux-interface] config/linux/interfaces/v2/interface/linux-tap | | Metadata: &{SwIfIndex:1 Vrf:0 IPAddresses:[192.168.1.1/30] TAPHostIfName:ta} | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-ip-scan-neighbor] config/vpp/v2/ipscanneigh-global TXN-26 OBTAINED | | scan_interval: 1 | | max_proc_time: 20 | | max_update: 10 | | scan_int_delay: 1 | | stale_threshold: 4 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-proxy-arp] config/vpp/v2/proxyarp-global TXN-26 OBTAINED | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/if/vpp-tap/vrf/0/dst/192.168.1.0/30/gw/0.0.0.0 TXN-26 OBTAINED | | dst_network: "192.168.1.1/30" | | next_hop_addr: "0.0.0.0" | | outgoing_interface: "vpp-tap" | | weight: 1 | | Depends on: | | - interface-exists -> config/vpp/v2/interfaces/vpp-tap | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/if/vpp-tap/vrf/0/dst/192.168.1.1/32/gw/192.168.1.1 TXN-26 OBTAINED | | dst_network: "192.168.1.1/32" | | next_hop_addr: "192.168.1.1" | | outgoing_interface: "vpp-tap" | | weight: 1 | | Depends on: | | - interface-exists -> config/vpp/v2/interfaces/vpp-tap | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/if/vpp-tap/vrf/0/dst/192.168.1.2/32/gw/192.168.1.2 TXN-26 OBTAINED | | dst_network: "192.168.1.2/32" | | next_hop_addr: "192.168.1.2" | | outgoing_interface: "vpp-tap" | | weight: 1 | | Depends on: | | - interface-exists -> config/vpp/v2/interfaces/vpp-tap | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/0.0.0.0/0/gw/0.0.0.0 TXN-26 OBTAINED | | type: DROP | | dst_network: "0.0.0.0/0" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/0.0.0.0/32/gw/0.0.0.0 TXN-26 OBTAINED | | type: DROP | | dst_network: "0.0.0.0/32" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/192.168.1.0/32/gw/0.0.0.0 TXN-26 OBTAINED | | type: DROP | | dst_network: "192.168.1.0/32" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/192.168.1.3/32/gw/0.0.0.0 TXN-26 OBTAINED | | type: DROP | | dst_network: "192.168.1.3/32" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/224.0.0.0/4/gw/0.0.0.0 TXN-26 OBTAINED | | type: DROP | | dst_network: "224.0.0.0/4" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/240.0.0.0/4/gw/0.0.0.0 TXN-26 OBTAINED | | type: DROP | | dst_network: "240.0.0.0/4" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/255.255.255.255/32/gw/0.0.0.0 TXN-26 OBTAINED | | type: DROP | | dst_network: "255.255.255.255/32" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/::/0/gw/:: TXN-26 OBTAINED | | type: DROP | | dst_network: "::/0" | | next_hop_addr: "::" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/fe80::/10/gw/:: TXN-26 OBTAINED | | dst_network: "fe80::/10" | | next_hop_addr: "::" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-vrf-table] config/vpp/v2/vrf-table/id/0/protocol/IPV4 (id/0/protocol/IPV4) TXN-26 OBTAINED | | label: "ipv4-VRF:0" | | Metadata: &{Index:0 Protocol:IPV4} | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-vrf-table] config/vpp/v2/vrf-table/id/0/protocol/IPV6 (id/0/protocol/IPV6) TXN-26 OBTAINED | | protocol: IPV6 | | label: "ipv6-VRF:0" | | Metadata: &{Index:0 Protocol:IPV6} | +----------------------------------------------------------------------------------------------------------------------+ | [linux-interface-watcher] linux/interface/host-name/eth0 TXN-26 OBTAINED | +----------------------------------------------------------------------------------------------------------------------+ | [linux-interface-watcher] linux/interface/host-name/lo TXN-26 OBTAINED | +----------------------------------------------------------------------------------------------------------------------+ | [linux-interface-watcher] linux/interface/host-name/tap-2870264825 TXN-28 OBTAINED | +----------------------------------------------------------------------------------------------------------------------+ | linux/link-local-route/linux-tap/dest-address/192.168.1.0/30 TXN-26 OBTAINED | | Derived from: config/linux/l3/v2/route/192.168.1.0/30/linux-tap | +----------------------------------------------------------------------------------------------------------------------+ | [microservice] linux/microservice/e2e-test-microservice1 TXN-26 OBTAINED | | Dependency for: | | - [linux-interface] config/linux/interfaces/v2/interface/linux-tap | | - [vpp-interface] config/vpp/v2/interfaces/vpp-tap | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-interface-link-state] vpp/interface/UNTAGGED-local0/link-state/DOWN TXN-26 OBTAINED | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-interface-address] vpp/interface/vpp-tap/address/static/192.168.1.1/30 TXN-26 CONFIGURED | | Depends on: | | - interface-assigned-to-vrf-table -> vpp/interface/vpp-tap/vrf/0/ip-version/v4 | | Dependency for: | | - [vpp-interface-has-address] vpp/interface/vpp-tap/has-IP-address | | Derived from: config/vpp/v2/interfaces/vpp-tap | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-interface-has-address] vpp/interface/vpp-tap/has-IP-address TXN-26 CONFIGURED | | Depends on: | | - interface-has-IP -> vpp/interface/vpp-tap/address/static/192.168.1.1/30 | | Derived from: config/vpp/v2/interfaces/vpp-tap | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-interface-link-state] vpp/interface/vpp-tap/link-state/UP TXN-26 OBTAINED | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-interface-vrf] vpp/interface/vpp-tap/vrf/0/ip-version/v4 TXN-26 CONFIGURED | | Dependency for: | | - [vpp-interface-address] vpp/interface/vpp-tap/address/static/192.168.1.1/30 | | Derived from: config/vpp/v2/interfaces/vpp-tap | +======================================================================================================================+ - 1. error (CREATE) config/linux/interfaces/v2/interface/linux-tap - LinkByName "ta\x04": Link not found time="2020-02-11 19:22:30.26547" level=error msg="LinkByName \"ta\\x04\": Link not found" loc="descriptor/interface_tap.go(55)" logger=linux-ifplugin.if-descriptor time="2020-02-11 19:22:30.26558" level=error msg="creating TAP_TO_VPP interface failed: Link not found\nLinkByName \"ta\\x04\"\ngo.ligato.io/vpp-agent/v3/plugins/linux/ifplugin/linuxcalls.(*NetLinkHandler).GetLinkByName\n\t/home/travis/gopath/src/go.ligato.io/vpp-agent/v3/plugins/linux/ifplugin/linuxcalls/link_linuxcalls.go:31\ngo.ligato.io/vpp-agent/v3/plugins/linux/ifplugin/linuxcalls.(*NetLinkHandler).SetInterfaceAlias\n\t/home/travis/gopath/src/go.ligato.io/vpp-agent/v3/plugins/linux/ifplugin/linuxcalls/link_linuxcalls.go:125\ngo.ligato.io/vpp-agent/v3/plugins/linux/ifplugin/descriptor.(*InterfaceDescriptor).createTAPToVPP\n\t/home/travis/gopath/src/go.ligato.io/vpp-agent/v3/plugins/linux/ifplugin/descriptor/interface_tap.go:53\ngo.ligato.io/vpp-agent/v3/plugins/linux/ifplugin/descriptor.(*InterfaceDescriptor).Create\n\t/home/travis/gopath/src/go.ligato.io/vpp-agent/v3/plugins/linux/ifplugin/descriptor/interface.go:319\ngo.ligato.io/vpp-agent/v3/plugins/linux/ifplugin/descriptor/adapter.(*InterfaceDescriptorAdapter).Create\n\t/home/travis/gopath/src/go.ligato.io/vpp-agent/v3/plugins/linux/ifplugin/descriptor/adapter/interface.go:115\ngo.ligato.io/vpp-agent/v3/plugins/kvscheduler.(*descriptorHandler).create\n\t/home/travis/gopath/src/go.ligato.io/vpp-agent/v3/plugins/kvscheduler/descriptor_handler.go:106\ngo.ligato.io/vpp-agent/v3/plugins/kvscheduler.(*Scheduler).applyCreate\n\t/home/travis/gopath/src/go.ligato.io/vpp-agent/v3/plugins/kvscheduler/txn_exec.go:448\ngo.ligato.io/vpp-agent/v3/plugins/kvscheduler.(*Scheduler).applyValue\n\t/home/travis/gopath/src/go.ligato.io/vpp-agent/v3/plugins/kvscheduler/txn_exec.go:241\ngo.ligato.io/vpp-agent/v3/plugins/kvscheduler.(*Scheduler).executeTransaction\n\t/home/travis/gopath/src/go.ligato.io/vpp-agent/v3/plugins/kvscheduler/txn_exec.go:85\ngo.ligato.io/vpp-agent/v3/plugins/kvscheduler.(*Scheduler).processTransaction\n\t/home/travis/gopath/src/go.ligato.io/vpp-agent/v3/plugins/kvscheduler/txn_process.go:149\ngo.ligato.io/vpp-agent/v3/plugins/kvscheduler.(*Scheduler).consumeTransactions\n\t/home/travis/gopath/src/go.ligato.io/vpp-agent/v3/plugins/kvscheduler/txn_process.go:95\nruntime.goexit\n\t/home/travis/.gimme/versions/go1.13.7.linux.amd64/src/runtime/asm_amd64.s:1357" loc="descriptor/interface.go(341)" logger=linux-ifplugin.if-descriptor time="2020-02-11 19:22:30.26726" level=error msg="Transaction #29 finished with 1 errors" loc="orchestrator/dispatcher.go(157)" logger=dispatcher +======================================================================================================================+ | #30 - Retry Transaction retrying TX #29 (attempt 1) | +======================================================================================================================+ * transaction arguments: - seqNum: 30 - type: Retry Transaction (for txn 29, attempt #1) - values: - key: config/linux/interfaces/v2/interface/linux-tap val: { name:"linux-tap" type:TAP_TO_VPP namespace: host_if_name:"tap" enabled:true ip_addresses:"192.168.1.2/30" tap: } * planned operations: 1. CREATE [RETRY]: - key: config/linux/interfaces/v2/interface/linux-tap - value: { name:"linux-tap" type:TAP_TO_VPP namespace: host_if_name:"tap" enabled:true ip_addresses:"192.168.1.2/30" tap: } - prev-error: LinkByName "ta\x04": Link not found 2. CREATE [DERIVED RETRY]: - key: linux/interface/linux-tap/address/static/192.168.1.2/30 - value: 3. CREATE [PROPERTY]: - key: linux/interface/state/linux-tap/UP - value: o----------------------------------------------------------------------------------------------------------------------o * executed operations (2020-02-11 19:22:31.267 +0000 UTC -> 2020-02-11 19:22:31.269 +0000 UTC, dur: 2ms): 1. CREATE [RETRY]: - key: config/linux/interfaces/v2/interface/linux-tap - value: { name:"linux-tap" type:TAP_TO_VPP namespace: host_if_name:"tap" enabled:true ip_addresses:"192.168.1.2/30" tap: } - prev-error: LinkByName "ta\x04": Link not found - error: LinkByName "ta\x04": Link not found x----------------------------------------------------------------------------------------------------------------------x | #30 - Retry Transaction took 1.8ms | x----------------------------------------------------------------------------------------------------------------------x time="2020-02-11 19:22:31.26875" level=error msg="LinkByName \"ta\\x04\": Link not found" loc="descriptor/interface_tap.go(55)" logger=linux-ifplugin.if-descriptor time="2020-02-11 19:22:31.26900" level=error msg="creating TAP_TO_VPP interface failed: Link not found\nLinkByName \"ta\\x04\"\ngo.ligato.io/vpp-agent/v3/plugins/linux/ifplugin/linuxcalls.(*NetLinkHandler).GetLinkByName\n\t/home/travis/gopath/src/go.ligato.io/vpp-agent/v3/plugins/linux/ifplugin/linuxcalls/link_linuxcalls.go:31\ngo.ligato.io/vpp-agent/v3/plugins/linux/ifplugin/linuxcalls.(*NetLinkHandler).SetInterfaceAlias\n\t/home/travis/gopath/src/go.ligato.io/vpp-agent/v3/plugins/linux/ifplugin/linuxcalls/link_linuxcalls.go:125\ngo.ligato.io/vpp-agent/v3/plugins/linux/ifplugin/descriptor.(*InterfaceDescriptor).createTAPToVPP\n\t/home/travis/gopath/src/go.ligato.io/vpp-agent/v3/plugins/linux/ifplugin/descriptor/interface_tap.go:53\ngo.ligato.io/vpp-agent/v3/plugins/linux/ifplugin/descriptor.(*InterfaceDescriptor).Create\n\t/home/travis/gopath/src/go.ligato.io/vpp-agent/v3/plugins/linux/ifplugin/descriptor/interface.go:319\ngo.ligato.io/vpp-agent/v3/plugins/linux/ifplugin/descriptor/adapter.(*InterfaceDescriptorAdapter).Create\n\t/home/travis/gopath/src/go.ligato.io/vpp-agent/v3/plugins/linux/ifplugin/descriptor/adapter/interface.go:115\ngo.ligato.io/vpp-agent/v3/plugins/kvscheduler.(*descriptorHandler).create\n\t/home/travis/gopath/src/go.ligato.io/vpp-agent/v3/plugins/kvscheduler/descriptor_handler.go:106\ngo.ligato.io/vpp-agent/v3/plugins/kvscheduler.(*Scheduler).applyCreate\n\t/home/travis/gopath/src/go.ligato.io/vpp-agent/v3/plugins/kvscheduler/txn_exec.go:448\ngo.ligato.io/vpp-agent/v3/plugins/kvscheduler.(*Scheduler).applyValue\n\t/home/travis/gopath/src/go.ligato.io/vpp-agent/v3/plugins/kvscheduler/txn_exec.go:241\ngo.ligato.io/vpp-agent/v3/plugins/kvscheduler.(*Scheduler).executeTransaction\n\t/home/travis/gopath/src/go.ligato.io/vpp-agent/v3/plugins/kvscheduler/txn_exec.go:85\ngo.ligato.io/vpp-agent/v3/plugins/kvscheduler.(*Scheduler).processTransaction\n\t/home/travis/gopath/src/go.ligato.io/vpp-agent/v3/plugins/kvscheduler/txn_process.go:149\ngo.ligato.io/vpp-agent/v3/plugins/kvscheduler.(*Scheduler).consumeTransactions\n\t/home/travis/gopath/src/go.ligato.io/vpp-agent/v3/plugins/kvscheduler/txn_process.go:95\nruntime.goexit\n\t/home/travis/.gimme/versions/go1.13.7.linux.amd64/src/runtime/asm_amd64.s:1357" loc="descriptor/interface.go(341)" logger=linux-ifplugin.if-descriptor +======================================================================================================================+ | GRAPH 33 nodes | +======================================================================================================================+ | [linux-interface] config/linux/interfaces/v2/interface/linux-tap (linux-tap) TXN-30 RETRYING | | name: "linux-tap" | | type: TAP_TO_VPP | | namespace: < | | type: MICROSERVICE | | reference: "e2e-test-microservice1" | | > | | host_if_name: "tap" | | enabled: true | | ip_addresses: "192.168.1.2/30" | | tap: < | | vpp_tap_if_name: "vpp-tap" | | > | | Depends on: | | - microservice-available -> linux/microservice/e2e-test-microservice1 | | - vpp-tap-interface-exists -> config/vpp/v2/interfaces/vpp-tap | | Derives: | | - linux/interface/linux-tap/address/static/192.168.1.2/30 | | - linux/interface/state/linux-tap/UP | | Errors: LinkByName "ta\x04": Link not found | +----------------------------------------------------------------------------------------------------------------------+ | [linux-arp] config/linux/l3/v2/arp/linux-tap/192.168.1.1 (linux-tap/192.168.1.1) TXN-26 OBTAINED | | interface: "linux-tap" | | ip_address: "192.168.1.1" | | hw_address: "02:fe:33:f1:dd:79" | | Depends on: | | - interface-has-ip-address -> | | - interface-is-up -> | +----------------------------------------------------------------------------------------------------------------------+ | [linux-route] config/linux/l3/v2/route/192.168.1.0/30/linux-tap (192.168.1.0/30/linux-tap) TXN-26 OBTAINED | | outgoing_interface: "linux-tap" | | scope: LINK | | dst_network: "192.168.1.0/30" | | Depends on: | | - outgoing-interface-has-ip-address -> | | - outgoing-interface-is-up -> | | Derives: | | - linux/link-local-route/linux-tap/dest-address/192.168.1.0/30 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-nat44-global] config/vpp/nat/v2/nat44-global TXN-26 OBTAINED | | virtual_reassembly: < | | timeout: 2 | | max_reassemblies: 1024 | | max_fragments: 5 | | > | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-arp] config/vpp/v2/arp/vpp-tap/192.168.1.2 (vpp-tap/192.168.1.2) TXN-26 OBTAINED | | interface: "vpp-tap" | | ip_address: "192.168.1.2" | | phys_address: "76:46:90:94:98:b5" | | Depends on: | | - interface-exists -> config/vpp/v2/interfaces/vpp-tap | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-interface] config/vpp/v2/interfaces/UNTAGGED-local0 (UNTAGGED-local0) TXN-26 OBTAINED | | name: "UNTAGGED-local0" | | type: SOFTWARE_LOOPBACK | | Metadata: &{SwIfIndex:0 Vrf:0 IPAddresses:[] TAPHostIfName:} | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-interface] config/vpp/v2/interfaces/vpp-tap (vpp-tap) TXN-26 CONFIGURED | | name: "vpp-tap" | | type: TAP | | enabled: true | | ip_addresses: "192.168.1.1/30" | | tap: < | | version: 2 | | to_microservice: "e2e-test-microservice1" | | > | | Depends on: | | - microservice-available -> linux/microservice/e2e-test-microservice1 | | Derives: | | - [vpp-interface-address] vpp/interface/vpp-tap/address/static/192.168.1.1/30 | | - [vpp-interface-has-address] vpp/interface/vpp-tap/has-IP-address | | - [vpp-interface-vrf] vpp/interface/vpp-tap/vrf/0/ip-version/v4 | | Dependency for: | | - [vpp-arp] config/vpp/v2/arp/vpp-tap/192.168.1.2 | | - [vpp-route] config/vpp/v2/route/if/vpp-tap/vrf/0/dst/192.168.1.0/30/gw/0.0.0.0 | | - [vpp-route] config/vpp/v2/route/if/vpp-tap/vrf/0/dst/192.168.1.1/32/gw/192.168.1.1 | | - [vpp-route] config/vpp/v2/route/if/vpp-tap/vrf/0/dst/192.168.1.2/32/gw/192.168.1.2 | | - [linux-interface] config/linux/interfaces/v2/interface/linux-tap | | Metadata: &{SwIfIndex:1 Vrf:0 IPAddresses:[192.168.1.1/30] TAPHostIfName:ta} | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-ip-scan-neighbor] config/vpp/v2/ipscanneigh-global TXN-26 OBTAINED | | scan_interval: 1 | | max_proc_time: 20 | | max_update: 10 | | scan_int_delay: 1 | | stale_threshold: 4 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-proxy-arp] config/vpp/v2/proxyarp-global TXN-26 OBTAINED | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/if/vpp-tap/vrf/0/dst/192.168.1.0/30/gw/0.0.0.0 TXN-26 OBTAINED | | dst_network: "192.168.1.1/30" | | next_hop_addr: "0.0.0.0" | | outgoing_interface: "vpp-tap" | | weight: 1 | | Depends on: | | - interface-exists -> config/vpp/v2/interfaces/vpp-tap | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/if/vpp-tap/vrf/0/dst/192.168.1.1/32/gw/192.168.1.1 TXN-26 OBTAINED | | dst_network: "192.168.1.1/32" | | next_hop_addr: "192.168.1.1" | | outgoing_interface: "vpp-tap" | | weight: 1 | | Depends on: | | - interface-exists -> config/vpp/v2/interfaces/vpp-tap | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/if/vpp-tap/vrf/0/dst/192.168.1.2/32/gw/192.168.1.2 TXN-26 OBTAINED | | dst_network: "192.168.1.2/32" | | next_hop_addr: "192.168.1.2" | | outgoing_interface: "vpp-tap" | | weight: 1 | | Depends on: | | - interface-exists -> config/vpp/v2/interfaces/vpp-tap | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/0.0.0.0/0/gw/0.0.0.0 TXN-26 OBTAINED | | type: DROP | | dst_network: "0.0.0.0/0" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/0.0.0.0/32/gw/0.0.0.0 TXN-26 OBTAINED | | type: DROP | | dst_network: "0.0.0.0/32" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/192.168.1.0/32/gw/0.0.0.0 TXN-26 OBTAINED | | type: DROP | | dst_network: "192.168.1.0/32" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/192.168.1.3/32/gw/0.0.0.0 TXN-26 OBTAINED | | type: DROP | | dst_network: "192.168.1.3/32" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/224.0.0.0/4/gw/0.0.0.0 TXN-26 OBTAINED | | type: DROP | | dst_network: "224.0.0.0/4" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/240.0.0.0/4/gw/0.0.0.0 TXN-26 OBTAINED | | type: DROP | | dst_network: "240.0.0.0/4" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/255.255.255.255/32/gw/0.0.0.0 TXN-26 OBTAINED | | type: DROP | | dst_network: "255.255.255.255/32" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/::/0/gw/:: TXN-26 OBTAINED | | type: DROP | | dst_network: "::/0" | | next_hop_addr: "::" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/fe80::/10/gw/:: TXN-26 OBTAINED | | dst_network: "fe80::/10" | | next_hop_addr: "::" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-vrf-table] config/vpp/v2/vrf-table/id/0/protocol/IPV4 (id/0/protocol/IPV4) TXN-26 OBTAINED | | label: "ipv4-VRF:0" | | Metadata: &{Index:0 Protocol:IPV4} | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-vrf-table] config/vpp/v2/vrf-table/id/0/protocol/IPV6 (id/0/protocol/IPV6) TXN-26 OBTAINED | | protocol: IPV6 | | label: "ipv6-VRF:0" | | Metadata: &{Index:0 Protocol:IPV6} | +----------------------------------------------------------------------------------------------------------------------+ | [linux-interface-watcher] linux/interface/host-name/eth0 TXN-26 OBTAINED | +----------------------------------------------------------------------------------------------------------------------+ | [linux-interface-watcher] linux/interface/host-name/lo TXN-26 OBTAINED | +----------------------------------------------------------------------------------------------------------------------+ | [linux-interface-watcher] linux/interface/host-name/tap-2870264825 TXN-28 OBTAINED | +----------------------------------------------------------------------------------------------------------------------+ | linux/link-local-route/linux-tap/dest-address/192.168.1.0/30 TXN-26 OBTAINED | | Derived from: config/linux/l3/v2/route/192.168.1.0/30/linux-tap | +----------------------------------------------------------------------------------------------------------------------+ | [microservice] linux/microservice/e2e-test-microservice1 TXN-26 OBTAINED | | Dependency for: | | - [linux-interface] config/linux/interfaces/v2/interface/linux-tap | | - [vpp-interface] config/vpp/v2/interfaces/vpp-tap | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-interface-link-state] vpp/interface/UNTAGGED-local0/link-state/DOWN TXN-26 OBTAINED | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-interface-address] vpp/interface/vpp-tap/address/static/192.168.1.1/30 TXN-26 CONFIGURED | | Depends on: | | - interface-assigned-to-vrf-table -> vpp/interface/vpp-tap/vrf/0/ip-version/v4 | | Dependency for: | | - [vpp-interface-has-address] vpp/interface/vpp-tap/has-IP-address | | Derived from: config/vpp/v2/interfaces/vpp-tap | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-interface-has-address] vpp/interface/vpp-tap/has-IP-address TXN-26 CONFIGURED | | Depends on: | | - interface-has-IP -> vpp/interface/vpp-tap/address/static/192.168.1.1/30 | | Derived from: config/vpp/v2/interfaces/vpp-tap | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-interface-link-state] vpp/interface/vpp-tap/link-state/UP TXN-26 OBTAINED | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-interface-vrf] vpp/interface/vpp-tap/vrf/0/ip-version/v4 TXN-26 CONFIGURED | | Dependency for: | | - [vpp-interface-address] vpp/interface/vpp-tap/address/static/192.168.1.1/30 | | Derived from: config/vpp/v2/interfaces/vpp-tap | +======================================================================================================================+ time="2020-02-11 19:22:31.29160" level=error msg="KeyErrors: [config/linux/interfaces/v2/interface/linux-tap (CREATE): LinkByName \"ta\\x04\": Link not found]" loc="kvscheduler/txn_process.go(404)" logger=kvscheduler +======================================================================================================================+ | #31 - Retry Transaction retrying TX #29 (attempt 2) | +======================================================================================================================+ * transaction arguments: - seqNum: 31 - type: Retry Transaction (for txn 29, attempt #2) - values: - key: config/linux/interfaces/v2/interface/linux-tap val: { name:"linux-tap" type:TAP_TO_VPP namespace: host_if_name:"tap" enabled:true ip_addresses:"192.168.1.2/30" tap: } * planned operations: 1. CREATE [RETRY]: - key: config/linux/interfaces/v2/interface/linux-tap - value: { name:"linux-tap" type:TAP_TO_VPP namespace: host_if_name:"tap" enabled:true ip_addresses:"192.168.1.2/30" tap: } - prev-error: LinkByName "ta\x04": Link not found 2. CREATE [DERIVED RETRY]: - key: linux/interface/linux-tap/address/static/192.168.1.2/30 - value: 3. CREATE [PROPERTY]: - key: linux/interface/state/linux-tap/UP - value: o----------------------------------------------------------------------------------------------------------------------o * executed operations (2020-02-11 19:22:33.3 +0000 UTC -> 2020-02-11 19:22:33.301 +0000 UTC, dur: 1ms): 1. CREATE [RETRY]: - key: config/linux/interfaces/v2/interface/linux-tap - value: { name:"linux-tap" type:TAP_TO_VPP namespace: host_if_name:"tap" enabled:true ip_addresses:"192.168.1.2/30" tap: } - prev-error: LinkByName "ta\x04": Link not found - error: LinkByName "ta\x04": Link not found x----------------------------------------------------------------------------------------------------------------------x | #31 - Retry Transaction took 1ms | x----------------------------------------------------------------------------------------------------------------------x +======================================================================================================================+ | GRAPH 33 nodes | +======================================================================================================================+ | [linux-interface] config/linux/interfaces/v2/interface/linux-tap (linux-tap) TXN-31 RETRYING | | name: "linux-tap" | | type: TAP_TO_VPP | | namespace: < | | type: MICROSERVICE | | reference: "e2e-test-microservice1" | | > | | host_if_name: "tap" | | enabled: true | | ip_addresses: "192.168.1.2/30" | | tap: < | | vpp_tap_if_name: "vpp-tap" | | > | | Depends on: | | - microservice-available -> linux/microservice/e2e-test-microservice1 | | - vpp-tap-interface-exists -> config/vpp/v2/interfaces/vpp-tap | | Derives: | | - linux/interface/linux-tap/address/static/192.168.1.2/30 | | - linux/interface/state/linux-tap/UP | | Errors: LinkByName "ta\x04": Link not found | +----------------------------------------------------------------------------------------------------------------------+ | [linux-arp] config/linux/l3/v2/arp/linux-tap/192.168.1.1 (linux-tap/192.168.1.1) TXN-26 OBTAINED | | interface: "linux-tap" | | ip_address: "192.168.1.1" | | hw_address: "02:fe:33:f1:dd:79" | | Depends on: | | - interface-has-ip-address -> | | - interface-is-up -> | +----------------------------------------------------------------------------------------------------------------------+ | [linux-route] config/linux/l3/v2/route/192.168.1.0/30/linux-tap (192.168.1.0/30/linux-tap) TXN-26 OBTAINED | | outgoing_interface: "linux-tap" | | scope: LINK | | dst_network: "192.168.1.0/30" | | Depends on: | | - outgoing-interface-has-ip-address -> | | - outgoing-interface-is-up -> | | Derives: | | - linux/link-local-route/linux-tap/dest-address/192.168.1.0/30 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-nat44-global] config/vpp/nat/v2/nat44-global TXN-26 OBTAINED | | virtual_reassembly: < | | timeout: 2 | | max_reassemblies: 1024 | | max_fragments: 5 | | > | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-arp] config/vpp/v2/arp/vpp-tap/192.168.1.2 (vpp-tap/192.168.1.2) TXN-26 OBTAINED | | interface: "vpp-tap" | | ip_address: "192.168.1.2" | | phys_address: "76:46:90:94:98:b5" | | Depends on: | | - interface-exists -> config/vpp/v2/interfaces/vpp-tap | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-interface] config/vpp/v2/interfaces/UNTAGGED-local0 (UNTAGGED-local0) TXN-26 OBTAINED | | name: "UNTAGGED-local0" | | type: SOFTWARE_LOOPBACK | | Metadata: &{SwIfIndex:0 Vrf:0 IPAddresses:[] TAPHostIfName:} | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-interface] config/vpp/v2/interfaces/vpp-tap (vpp-tap) TXN-26 CONFIGURED | | name: "vpp-tap" | | type: TAP | | enabled: true | | ip_addresses: "192.168.1.1/30" | | tap: < | | version: 2 | | to_microservice: "e2e-test-microservice1" | | > | | Depends on: | | - microservice-available -> linux/microservice/e2e-test-microservice1 | | Derives: | | - [vpp-interface-address] vpp/interface/vpp-tap/address/static/192.168.1.1/30 | | - [vpp-interface-has-address] vpp/interface/vpp-tap/has-IP-address | | - [vpp-interface-vrf] vpp/interface/vpp-tap/vrf/0/ip-version/v4 | | Dependency for: | | - [vpp-arp] config/vpp/v2/arp/vpp-tap/192.168.1.2 | | - [vpp-route] config/vpp/v2/route/if/vpp-tap/vrf/0/dst/192.168.1.0/30/gw/0.0.0.0 | | - [vpp-route] config/vpp/v2/route/if/vpp-tap/vrf/0/dst/192.168.1.1/32/gw/192.168.1.1 | | - [vpp-route] config/vpp/v2/route/if/vpp-tap/vrf/0/dst/192.168.1.2/32/gw/192.168.1.2 | | - [linux-interface] config/linux/interfaces/v2/interface/linux-tap | | Metadata: &{SwIfIndex:1 Vrf:0 IPAddresses:[192.168.1.1/30] TAPHostIfName:ta} | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-ip-scan-neighbor] config/vpp/v2/ipscanneigh-global TXN-26 OBTAINED | | scan_interval: 1 | | max_proc_time: 20 | | max_update: 10 | | scan_int_delay: 1 | | stale_threshold: 4 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-proxy-arp] config/vpp/v2/proxyarp-global TXN-26 OBTAINED | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/if/vpp-tap/vrf/0/dst/192.168.1.0/30/gw/0.0.0.0 TXN-26 OBTAINED | | dst_network: "192.168.1.1/30" | | next_hop_addr: "0.0.0.0" | | outgoing_interface: "vpp-tap" | | weight: 1 | | Depends on: | | - interface-exists -> config/vpp/v2/interfaces/vpp-tap | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/if/vpp-tap/vrf/0/dst/192.168.1.1/32/gw/192.168.1.1 TXN-26 OBTAINED | | dst_network: "192.168.1.1/32" | | next_hop_addr: "192.168.1.1" | | outgoing_interface: "vpp-tap" | | weight: 1 | | Depends on: | | - interface-exists -> config/vpp/v2/interfaces/vpp-tap | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/if/vpp-tap/vrf/0/dst/192.168.1.2/32/gw/192.168.1.2 TXN-26 OBTAINED | | dst_network: "192.168.1.2/32" | | next_hop_addr: "192.168.1.2" | | outgoing_interface: "vpp-tap" | | weight: 1 | | Depends on: | | - interface-exists -> config/vpp/v2/interfaces/vpp-tap | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/0.0.0.0/0/gw/0.0.0.0 TXN-26 OBTAINED | | type: DROP | | dst_network: "0.0.0.0/0" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/0.0.0.0/32/gw/0.0.0.0 TXN-26 OBTAINED | | type: DROP | | dst_network: "0.0.0.0/32" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/192.168.1.0/32/gw/0.0.0.0 TXN-26 OBTAINED | | type: DROP | | dst_network: "192.168.1.0/32" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/192.168.1.3/32/gw/0.0.0.0 TXN-26 OBTAINED | | type: DROP | | dst_network: "192.168.1.3/32" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/224.0.0.0/4/gw/0.0.0.0 TXN-26 OBTAINED | | type: DROP | | dst_network: "224.0.0.0/4" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/240.0.0.0/4/gw/0.0.0.0 TXN-26 OBTAINED | | type: DROP | | dst_network: "240.0.0.0/4" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/255.255.255.255/32/gw/0.0.0.0 TXN-26 OBTAINED | | type: DROP | | dst_network: "255.255.255.255/32" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/::/0/gw/:: TXN-26 OBTAINED | | type: DROP | | dst_network: "::/0" | | next_hop_addr: "::" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/fe80::/10/gw/:: TXN-26 OBTAINED | | dst_network: "fe80::/10" | | next_hop_addr: "::" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-vrf-table] config/vpp/v2/vrf-table/id/0/protocol/IPV4 (id/0/protocol/IPV4) TXN-26 OBTAINED | | label: "ipv4-VRF:0" | | Metadata: &{Index:0 Protocol:IPV4} | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-vrf-table] config/vpp/v2/vrf-table/id/0/protocol/IPV6 (id/0/protocol/IPV6) TXN-26 OBTAINED | | protocol: IPV6 | | label: "ipv6-VRF:0" | | Metadata: &{Index:0 Protocol:IPV6} | +----------------------------------------------------------------------------------------------------------------------+ | [linux-interface-watcher] linux/interface/host-name/eth0 TXN-26 OBTAINED | +----------------------------------------------------------------------------------------------------------------------+ | [linux-interface-watcher] linux/interface/host-name/lo TXN-26 OBTAINED | +----------------------------------------------------------------------------------------------------------------------+ | [linux-interface-watcher] linux/interface/host-name/tap-2870264825 TXN-28 OBTAINED | +----------------------------------------------------------------------------------------------------------------------+ | linux/link-local-route/linux-tap/dest-address/192.168.1.0/30 TXN-26 OBTAINED | | Derived from: config/linux/l3/v2/route/192.168.1.0/30/linux-tap | +----------------------------------------------------------------------------------------------------------------------+ | [microservice] linux/microservice/e2e-test-microservice1 TXN-26 OBTAINED | | Dependency for: | | - [linux-interface] config/linux/interfaces/v2/interface/linux-tap | | - [vpp-interface] config/vpp/v2/interfaces/vpp-tap | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-interface-link-state] vpp/interface/UNTAGGED-local0/link-state/DOWN TXN-26 OBTAINED | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-interface-address] vpp/interface/vpp-tap/address/static/192.168.1.1/30 TXN-26 CONFIGURED | | Depends on: | | - interface-assigned-to-vrf-table -> vpp/interface/vpp-tap/vrf/0/ip-version/v4 | | Dependency for: | | - [vpp-interface-has-address] vpp/interface/vpp-tap/has-IP-address | | Derived from: config/vpp/v2/interfaces/vpp-tap | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-interface-has-address] vpp/interface/vpp-tap/has-IP-address TXN-26 CONFIGURED | | Depends on: | | - interface-has-IP -> vpp/interface/vpp-tap/address/static/192.168.1.1/30 | | Derived from: config/vpp/v2/interfaces/vpp-tap | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-interface-link-state] vpp/interface/vpp-tap/link-state/UP TXN-26 OBTAINED | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-interface-vrf] vpp/interface/vpp-tap/vrf/0/ip-version/v4 TXN-26 CONFIGURED | | Dependency for: | | - [vpp-interface-address] vpp/interface/vpp-tap/address/static/192.168.1.1/30 | | Derived from: config/vpp/v2/interfaces/vpp-tap | +======================================================================================================================+ time="2020-02-11 19:22:33.30037" level=error msg="LinkByName \"ta\\x04\": Link not found" loc="descriptor/interface_tap.go(55)" logger=linux-ifplugin.if-descriptor time="2020-02-11 19:22:33.30051" level=error msg="creating TAP_TO_VPP interface failed: Link not found\nLinkByName \"ta\\x04\"\ngo.ligato.io/vpp-agent/v3/plugins/linux/ifplugin/linuxcalls.(*NetLinkHandler).GetLinkByName\n\t/home/travis/gopath/src/go.ligato.io/vpp-agent/v3/plugins/linux/ifplugin/linuxcalls/link_linuxcalls.go:31\ngo.ligato.io/vpp-agent/v3/plugins/linux/ifplugin/linuxcalls.(*NetLinkHandler).SetInterfaceAlias\n\t/home/travis/gopath/src/go.ligato.io/vpp-agent/v3/plugins/linux/ifplugin/linuxcalls/link_linuxcalls.go:125\ngo.ligato.io/vpp-agent/v3/plugins/linux/ifplugin/descriptor.(*InterfaceDescriptor).createTAPToVPP\n\t/home/travis/gopath/src/go.ligato.io/vpp-agent/v3/plugins/linux/ifplugin/descriptor/interface_tap.go:53\ngo.ligato.io/vpp-agent/v3/plugins/linux/ifplugin/descriptor.(*InterfaceDescriptor).Create\n\t/home/travis/gopath/src/go.ligato.io/vpp-agent/v3/plugins/linux/ifplugin/descriptor/interface.go:319\ngo.ligato.io/vpp-agent/v3/plugins/linux/ifplugin/descriptor/adapter.(*InterfaceDescriptorAdapter).Create\n\t/home/travis/gopath/src/go.ligato.io/vpp-agent/v3/plugins/linux/ifplugin/descriptor/adapter/interface.go:115\ngo.ligato.io/vpp-agent/v3/plugins/kvscheduler.(*descriptorHandler).create\n\t/home/travis/gopath/src/go.ligato.io/vpp-agent/v3/plugins/kvscheduler/descriptor_handler.go:106\ngo.ligato.io/vpp-agent/v3/plugins/kvscheduler.(*Scheduler).applyCreate\n\t/home/travis/gopath/src/go.ligato.io/vpp-agent/v3/plugins/kvscheduler/txn_exec.go:448\ngo.ligato.io/vpp-agent/v3/plugins/kvscheduler.(*Scheduler).applyValue\n\t/home/travis/gopath/src/go.ligato.io/vpp-agent/v3/plugins/kvscheduler/txn_exec.go:241\ngo.ligato.io/vpp-agent/v3/plugins/kvscheduler.(*Scheduler).executeTransaction\n\t/home/travis/gopath/src/go.ligato.io/vpp-agent/v3/plugins/kvscheduler/txn_exec.go:85\ngo.ligato.io/vpp-agent/v3/plugins/kvscheduler.(*Scheduler).processTransaction\n\t/home/travis/gopath/src/go.ligato.io/vpp-agent/v3/plugins/kvscheduler/txn_process.go:149\ngo.ligato.io/vpp-agent/v3/plugins/kvscheduler.(*Scheduler).consumeTransactions\n\t/home/travis/gopath/src/go.ligato.io/vpp-agent/v3/plugins/kvscheduler/txn_process.go:95\nruntime.goexit\n\t/home/travis/.gimme/versions/go1.13.7.linux.amd64/src/runtime/asm_amd64.s:1357" loc="descriptor/interface.go(341)" logger=linux-ifplugin.if-descriptor time="2020-02-11 19:22:33.30204" level=error msg="KeyErrors: [config/linux/interfaces/v2/interface/linux-tap (CREATE): LinkByName \"ta\\x04\": Link not found]" loc="kvscheduler/txn_process.go(404)" logger=kvscheduler +======================================================================================================================+ | #32 - SB Notification | +======================================================================================================================+ * transaction arguments: - seqNum: 32 - type: SB Notification - values: - key: linux/microservice/e2e-test-microservice1 val: time="2020-02-11 19:22:33.50973" level=info msg="Signal terminated received, stopping." loc="agent/agent.go(196)" logger=agent time="2020-02-11 19:22:33.50981" level=info msg="Stopping agent" loc="agent/agent.go(269)" logger=agent o----------------------------------------------------------------------------------------------------------------------o * executed operations (2020-02-11 19:22:33.494 +0000 UTC -> 2020-02-11 19:22:33.535 +0000 UTC, dur: 40ms): 1. DELETE [DERIVED]: - key: vpp/interface/vpp-tap/has-IP-address - value: 2. DELETE [DERIVED]: - key: vpp/interface/vpp-tap/address/static/192.168.1.1/30 - value: 3. DELETE [DERIVED]: - key: vpp/interface/vpp-tap/vrf/0/ip-version/v4 - value: 4. DELETE [IS-PENDING]: - key: config/vpp/v2/interfaces/vpp-tap - value: { name:"vpp-tap" type:TAP enabled:true ip_addresses:"192.168.1.1/30" tap: } 5. DELETE [WAS-OBTAINED]: - key: linux/microservice/e2e-test-microservice1 - value: x----------------------------------------------------------------------------------------------------------------------x | #32 - SB Notification took 40.3ms | x----------------------------------------------------------------------------------------------------------------------x +======================================================================================================================+ | #33 - SB Notification | +======================================================================================================================+ * transaction arguments: - seqNum: 33 - type: SB Notification - values: - key: linux/interface/host-name/tap-2870264825 val: time="2020-02-11 19:22:33.53479" level=info msg="Transaction 32 successful!" loc="kvscheduler/txn_process.go(402)" logger=kvscheduler o----------------------------------------------------------------------------------------------------------------------o * executed operations (2020-02-11 19:22:33.535 +0000 UTC -> 2020-02-11 19:22:33.535 +0000 UTC, dur: 0s): 1. DELETE [WAS-OBTAINED]: - key: linux/interface/host-name/tap-2870264825 - value: x----------------------------------------------------------------------------------------------------------------------x | #33 - SB Notification took 400µs | x----------------------------------------------------------------------------------------------------------------------x time="2020-02-11 19:22:33.53566" level=info msg="Transaction 33 successful!" loc="kvscheduler/txn_process.go(402)" logger=kvscheduler time="2020-02-11 19:22:33.53660" level=info msg="Agent stopped" loc="agent/agent.go(291)" logger=agent PASS coverage: 29.2% of statements in go.ligato.io/vpp-agent/v3/... /usr/bin/vpp[5382]: received SIGTERM, exiting... /usr/bin/vpp[5382]: unix_signal_handler:170: received signal SIGTERM, PC 0x7fdaf137899d --- FAIL: TestTapInterfaceConn (70.24s) e2e_test.go:613: VPP start OK (PID: 5382) e2e_test.go:157: Using docker client endpoint: unix:///var/run/docker.sock e2e_test.go:613: VPP-Agent start OK (PID: 5383) e2e_test.go:565: agent ready, took 101.101429ms e2e_test.go:300: exec: vppctl ping 192.168.1.2 e2e_test.go:371: VPP ping 192.168.1.2: sent=5, received=4, loss=20% microservice_test.go:177: Linux ping 192.168.1.1: sent=5, received=4, loss=20% e2e_test.go:300: exec: vppctl ping 192.168.1.2 e2e_test.go:371: VPP ping 192.168.1.2: sent=0, received=0, loss=0% e2e_test.go:300: exec: vppctl ping 192.168.1.2 e2e_test.go:371: VPP ping 192.168.1.2: sent=5, received=4, loss=20% microservice_test.go:177: Linux ping 192.168.1.1: sent=5, received=4, loss=20% e2e_test.go:300: exec: vppctl ping 192.168.1.2 e2e_test.go:371: VPP ping 192.168.1.2: sent=0, received=0, loss=0% e2e_test.go:300: exec: vppctl ping 192.168.1.2 e2e_test.go:371: VPP ping 192.168.1.2: sent=5, received=4, loss=20% microservice_test.go:177: Linux ping 192.168.1.1: sent=5, received=4, loss=20% e2e_test.go:300: exec: vppctl ping 192.168.1.2 e2e_test.go:371: VPP ping 192.168.1.2: sent=0, received=0, loss=0% e2e_test.go:300: exec: vppctl ping 192.168.1.2 e2e_test.go:371: VPP ping 192.168.1.2: sent=5, received=4, loss=20% microservice_test.go:177: Linux ping 192.168.1.1: sent=5, received=4, loss=20% e2e_test.go:300: exec: vppctl ping 192.168.1.2 e2e_test.go:371: VPP ping 192.168.1.2: sent=5, received=0, loss=100% 010_interfaces_test.go:136: Expected error: <*status.statusError | 0xc0004ea190>: { Code: 9, Message: "KeyErrors: [config/linux/interfaces/v2/interface/linux-tap (CREATE): LinkByName \"ta\\x04\": Link not found]", Details: nil, XXX_NoUnkeyedLiteral: {}, XXX_unrecognized: nil, XXX_sizecache: 0, } rpc error: code = FailedPrecondition desc = KeyErrors: [config/linux/interfaces/v2/interface/linux-tap (CREATE): LinkByName "ta\x04": Link not found] not to have occurred e2e_test.go:209: ----------------- e2e_test.go:634: VPP-Agent exit OK e2e_test.go:634: VPP exit OK === RUN TestAfPacketInterfaceConn ``` > full log here: https://travis-ci.com/ligato/vpp-agent/jobs/286038603

Here's failing Travis job: https://travis-ci.com/ligato/vpp-agent/jobs/286038603

Any idea why this might be happening?

cc @milanlenco @rewenset

rewenset commented 4 years ago

Regarding TestTapInterfaceConn:

It is sometimes fails to create TAP_TO_VPP interface after it was removed. And the error says it is unable to find a link for name "ta\x04", therefore it is not problem of that "GetLinkByName" method. Weird things happening a little bit earlier, here: https://github.com/ligato/vpp-agent/blob/de6c10f0f7d9b940b4d2c18c8d957e94e291f261/plugins/vpp/ifplugin/ifaceidx/ifaceidx.go#L108-L116

So, "createTAPToVPP" method uses interface index from vpp plugin to get meta things. And when test passes it is:

vppTapMeta: &{SwIfIndex:1 Vrf:0 IPAddresses:[192.168.1.1/30] TAPHostIfName:tap-2870264825}
TAPHostIfName in bytes: [116 97 112 45 50 56 55 48 50 54 52 56 50 53]

but when it fails:

vppTapMeta: &{SwIfIndex:1 Vrf:0 IPAddresses:[192.168.1.1/30] TAPHostIfName:ta}
TAPHostIfName in bytes: [116 97 4]

That's all for now. I'm able to reproduce it, but not every time. It is more passes than fails.

ondrej-fabry commented 4 years ago

It seems that the TAPHostIfName gets corrupted somewhere. This will need more investigation.

Just a thought.. perhaps, it might be related to some race conditions reported by testing with -race. Those might need to be fixed first.

ondrej-fabry commented 4 years ago

Another recent failure in E2E test for VPP 19.08.

In this test the agent seems to receive SB notification about removed microservice, then the VPP seems to throw epoll_ctl: Bad file descriptor (errno 9) after which agent loses binapi connection to VPP and test fails while waiting for CONFIGURED state for AF_PACKET interface with name vpp-afpacket.

Relevant part of agent log during failed test:

...
+======================================================================================================================+
| #6 - SB Notification                                                                                                 |
+======================================================================================================================+
  * transaction arguments:
      - seqNum: 6
      - type: SB Notification
      - values:
          - key: linux/microservice/e2e-test-microservice1
            val: <NIL>

/usr/bin/vpp[6947]: linux_epoll_file_update:120: epoll_ctl: Bad file descriptor (errno 9)
time="2020-02-19 19:27:30.75809" level=info msg="Signal terminated received, stopping." loc="agent/agent.go(196)" logger=agent
time="2020-02-19 19:27:30.75818" level=info msg="Stopping agent" loc="agent/agent.go(269)" logger=agent
time="2020-02-19 19:27:31.75149" level=error msg="failed to remove interface vpp-afpacket, index 1: no reply received within the timeout period 1s" loc="descriptor/interface_crud.go(306)" logger=vpp-ifplugin.if-descriptor
time="2020-02-19 19:27:31.75181" level=error msg="LinkByName \"veth1\": Link not found" loc="descriptor/interface_veth.go(115)" logger=linux-ifplugin.if-descriptor
time="2020-02-19 19:27:31.75200" level=error msg="switch to namespace failed:Microservice 'e2e-test-microservice1' is not available" loc="descriptor/interface.go(416)" logger=linux-ifplugin.if-descriptor
time="2020-02-19 19:27:31.75289" level=error msg="failed to retrieve values: failed to dump memif socket details: not connected to VPP, ignoring the request" descriptor=vpp-interface loc="kvscheduler/refresh.go(121)" logger=kvscheduler
time="2020-02-19 19:27:31.75386" level=error msg="KeyErrors: [config/vpp/v2/interfaces/vpp-afpacket (DELETE): failed to remove interface vpp-afpacket, index 1: no reply received within the timeout period 1s, config/linux/interfaces/v2/interface/linux-veth1 (DELETE): LinkByName \"veth1\": Link not found, config/linux/interfaces/v2/interface/linux-veth2 (DELETE): Microservice 'e2e-test-microservice1' is not available]" loc="kvscheduler/txn_process.go(404)" logger=kvscheduler
...

Complete log of failed test: --- FAIL: TestAfPacketWithLogicalReference (5.11s)

``` === RUN TestAfPacketWithLogicalReference vlib_plugin_early_init:361: plugin path /usr/lib/x86_64-linux-gnu/vpp_plugins:/usr/lib/vpp_plugins load_one_plugin:189: Loaded plugin: abf_plugin.so (Access Control List (ACL) Based Forwarding) load_one_plugin:189: Loaded plugin: acl_plugin.so (Access Control Lists (ACL)) load_one_plugin:189: Loaded plugin: avf_plugin.so (Intel Adaptive Virtual Function (AVF) Device Driver) load_one_plugin:189: Loaded plugin: cdp_plugin.so (Cisco Discovery Protocol (CDP)) load_one_plugin:189: Loaded plugin: crypto_ia32_plugin.so (Intel IA32 Software Crypto Engine) load_one_plugin:189: Loaded plugin: crypto_ipsecmb_plugin.so (Intel IPSEC Multi-buffer Crypto Engine) load_one_plugin:189: Loaded plugin: crypto_openssl_plugin.so (OpenSSL Crypto Engine) load_one_plugin:189: Loaded plugin: ct6_plugin.so (IPv6 Connection Tracker) load_one_plugin:189: Loaded plugin: dns_plugin.so (Simple DNS name resolver) load_one_plugin:106: Plugin disabled: dpdk_plugin.so load_one_plugin:189: Loaded plugin: flowprobe_plugin.so (Flow per Packet) load_one_plugin:189: Loaded plugin: gbp_plugin.so (Group Based Policy (GBP)) load_one_plugin:189: Loaded plugin: gtpu_plugin.so (GPRS Tunnelling Protocol, User Data (GTPv1-U)) load_one_plugin:189: Loaded plugin: hs_apps_plugin.so (Host Stack Applications) load_one_plugin:189: Loaded plugin: http_static_plugin.so (HTTP Static Server) load_one_plugin:189: Loaded plugin: igmp_plugin.so (Internet Group Management Protocol (IGMP)) load_one_plugin:189: Loaded plugin: ikev2_plugin.so (Internet Key Exchange (IKEv2) Protocol) load_one_plugin:189: Loaded plugin: ila_plugin.so (Identifier Locator Addressing (ILA) for IPv6) load_one_plugin:189: Loaded plugin: ioam_plugin.so (Inbound Operations, Administration, and Maintenance (OAM)) load_one_plugin:117: Plugin disabled (default): ixge_plugin.so load_one_plugin:189: Loaded plugin: l2e_plugin.so (Layer 2 (L2) Emulation) load_one_plugin:189: Loaded plugin: l3xc_plugin.so (L3 Cross-Connect (L3XC)) load_one_plugin:189: Loaded plugin: lacp_plugin.so (Link Aggregation Control Protocol (LACP)) load_one_plugin:189: Loaded plugin: lb_plugin.so (Load Balancer (LB)) load_one_plugin:189: Loaded plugin: mactime_plugin.so (Time-based MAC Source Address Filter) load_one_plugin:189: Loaded plugin: map_plugin.so (Mapping of Address and Port (MAP)) load_one_plugin:189: Loaded plugin: memif_plugin.so (Packet Memory Interface (memif) -- Experimental) load_one_plugin:189: Loaded plugin: nat_plugin.so (Network Address Translation (NAT)) load_one_plugin:189: Loaded plugin: nsh_plugin.so (Network Service Header (NSH)) load_one_plugin:189: Loaded plugin: nsim_plugin.so (Network Delay Simulator) load_one_plugin:117: Plugin disabled (default): oddbuf_plugin.so load_one_plugin:189: Loaded plugin: perfmon_plugin.so (Performance Monitor) load_one_plugin:189: Loaded plugin: ping_plugin.so (Ping (ping)) load_one_plugin:189: Loaded plugin: pppoe_plugin.so (PPP over Ethernet (PPPoE)) load_one_plugin:117: Plugin disabled (default): quic_plugin.so load_one_plugin:189: Loaded plugin: rdma_plugin.so (RDMA IBverbs Device Driver) load_one_plugin:117: Plugin disabled (default): sctp_plugin.so load_one_plugin:189: Loaded plugin: srv6ad_plugin.so (Dynamic Segment Routing for IPv6 (SRv6) Proxy) load_one_plugin:189: Loaded plugin: srv6am_plugin.so (Masquerading Segment Routing for IPv6 (SRv6) Proxy) load_one_plugin:189: Loaded plugin: srv6as_plugin.so (Static Segment Routing for IPv6 (SRv6) Proxy) load_one_plugin:189: Loaded plugin: stn_plugin.so (VPP Steals the NIC (STN) for Container Integration) load_one_plugin:189: Loaded plugin: svs_plugin.so (Source Virtual Routing and Fowarding (VRF) Select) load_one_plugin:189: Loaded plugin: tlsmbedtls_plugin.so (Transport Layer Security (TLS) Engine, Mbedtls Based) load_one_plugin:189: Loaded plugin: tlsopenssl_plugin.so (Transport Layer Security (TLS) Engine, OpenSSL Based) load_one_plugin:117: Plugin disabled (default): unittest_plugin.so load_one_plugin:189: Loaded plugin: vmxnet3_plugin.so (VMWare Vmxnet3 Device Driver) /usr/bin/vpp[6947]: clib_elf_parse_file: open `linux-vdso.so.1': No such file or directory /usr/bin/vpp[6947]: load_one_vat_plugin:67: Loaded plugin: dns_test_plugin.so /usr/bin/vpp[6947]: load_one_vat_plugin:67: Loaded plugin: mactime_test_plugin.so /usr/bin/vpp[6947]: load_one_vat_plugin:67: Loaded plugin: vmxnet3_test_plugin.so /usr/bin/vpp[6947]: load_one_vat_plugin:67: Loaded plugin: nat_test_plugin.so /usr/bin/vpp[6947]: load_one_vat_plugin:67: Loaded plugin: acl_test_plugin.so /usr/bin/vpp[6947]: load_one_vat_plugin:67: Loaded plugin: lb_test_plugin.so /usr/bin/vpp[6947]: load_one_vat_plugin:67: Loaded plugin: memif_test_plugin.so /usr/bin/vpp[6947]: vat_plugin_register: gtpu plugin not loaded... /usr/bin/vpp[6947]: vat_plugin_register: pppoe plugin not loaded... /usr/bin/vpp[6947]: load_one_vat_plugin:67: Loaded plugin: http_static_test_plugin.so /usr/bin/vpp[6947]: load_one_vat_plugin:67: Loaded plugin: nsh_test_plugin.so /usr/bin/vpp[6947]: load_one_vat_plugin:67: Loaded plugin: stn_test_plugin.so /usr/bin/vpp[6947]: load_one_vat_plugin:67: Loaded plugin: lacp_test_plugin.so /usr/bin/vpp[6947]: vat_plugin_register: avf plugin not loaded... /usr/bin/vpp[6947]: load_one_vat_plugin:67: Loaded plugin: cdp_test_plugin.so /usr/bin/vpp[6947]: vat_plugin_register: oddbuf plugin not loaded... /usr/bin/vpp[6947]: load_one_vat_plugin:67: Loaded plugin: nsim_test_plugin.so /usr/bin/vpp[6947]: load_one_vat_plugin:67: Loaded plugin: ct6_test_plugin.so /usr/bin/vpp[6947]: load_one_vat_plugin:67: Loaded plugin: flowprobe_test_plugin.so /usr/bin/vpp[6947]: load_one_vat_plugin:67: Loaded plugin: ikev2_test_plugin.so /usr/bin/vpp[6947]: load_one_vat_plugin:67: Loaded plugin: ioam_test_plugin.so flag provided but not defined: -test.coverprofile __ _ _____ ___ _______ ____ ____ ___ / /_ | |/ / _ \/ _ /___/ _ '/ _ '/ -_/ _ / __/ vpp-agent v3.1.0-dev |___/ .__/ .__/ \_'_/\_' /\__/_//_\__/ Wed Feb 19 19:27:27 UTC 2020 (just now) /_/ /_/ /___/ unknown@unknown (go1.13.8 linux/amd64) time="2020-02-19 19:27:27.18580" level=info msg="Starting agent version: v3.1.0-dev" BuildDate="Wed Feb 19 19:27:27 UTC 2020" CommitHash=unknown loc="agent/agent.go(134)" logger=agent time="2020-02-19 19:27:27.18685" level=info msg="ETCD config not found, skip loading this plugin" loc="etcd/plugin_impl_etcd.go(293)" logger=etcd time="2020-02-19 19:27:27.18696" level=info msg="Consul config not found, skip loading this plugin" loc="consul/plugin.go(138)" logger=consul time="2020-02-19 19:27:27.18713" level=info msg="Redis config not found, skip loading this plugin" loc="redis/plugin_impl_redis.go(123)" logger=redis time="2020-02-19 19:27:27.19494" level=info msg="VPP version: 19.08.1-380~gde1aa39a5~b107\x00\x00\x00\x00\x00" ClientID=0 PID=6947 loc="govppmux/plugin_impl_govppmux.go(304)" logger=govpp time="2020-02-19 19:27:27.19837" level=info msg="starting VPP proxy" loc="govppmux/plugin_impl_govppmux.go(395)" logger=govpp 2020/02/19 19:27:27 rpc.Register: method "Connect" has 2 input parameters; needs exactly three 2020/02/19 19:27:27 rpc.Register: method "Disconnect" has 1 input parameters; needs exactly three 2020/02/19 19:27:27 rpc.Register: method "Connect" has 2 input parameters; needs exactly three 2020/02/19 19:27:27 rpc.Register: method "Disconnect" has 1 input parameters; needs exactly three time="2020-02-19 19:27:27.20013" level=info msg="VPP proxy ready" loc="govppmux/plugin_impl_govppmux.go(169)" logger=govpp time="2020-02-19 19:27:27.20052" level=info msg="Namespace plugin initialized" loc="nsplugin/ns_plugin.go(111)" logger=linux-nsplugin time="2020-02-19 19:27:27.20094" level=info msg="kafka config not found - skip loading this plugin" loc="kafka/plugin_impl_kafka.go(73)" logger=kafka time="2020-02-19 19:27:27.20265" level=info msg="registering grpc reflection service" loc="orchestrator/orchestrator.go(87)" logger=orchestrator time="2020-02-19 19:27:27.20284" level=info msg="Watch starting for 33 registered NB prefixes" loc="orchestrator/orchestrator.go(96)" logger=dispatcher time="2020-02-19 19:27:27.20379" level=info msg="Listening on http://0.0.0.0:9191" loc="rest/plugin_impl_rest.go(109)" logger=http time="2020-02-19 19:27:27.20409" level=info msg="Agent plugin state update." lastErr="" loc="statuscheck/plugin_impl_statuscheck.go(183)" logger=status-check plugin=govpp state=ok time="2020-02-19T19:27:27Z" level=info msg="enabling statsRPC service" time="2020-02-19T19:27:27Z" level=info msg="enabling binapiRPC service" time="2020-02-19 19:27:27.20822" level=info msg="HTTP not set, skip exposing GRPC services" loc="grpc/plugin_impl_grpc.go(119)" logger=grpc time="2020-02-19 19:27:27.20855" level=info msg="Listening GRPC on: 127.0.0.1:9111" loc="grpc/plugin_impl_grpc.go(127)" logger=grpc time="2020-02-19 19:27:27.21225" level=info msg="Starting health http-probe on port 9191" loc="probe/plugin_impl_probe.go(75)" logger=probe time="2020-02-19 19:27:27.21258" level=info msg="Unable to register prometheus-probe handler, Prometheus is nil" loc="probe/plugin_impl_probe.go(87)" logger=probe time="2020-02-19 19:27:27.21293" level=info msg="Serving /metrics on port 9191" loc="prometheus/plugin_impl_prometheus.go(88)" logger=prometheus time="2020-02-19 19:27:27.21322" level=warning msg="No registrations, skipping resync" loc="resync/plugin_impl_resync.go(98)" logger=resync time="2020-02-19 19:27:27.21350" level=info msg="Agent plugin state update." lastErr="" loc="statuscheck/plugin_impl_statuscheck.go(183)" logger=status-check plugin=VPPAgent state=ok time="2020-02-19 19:27:27.21381" level=info msg="Agent started with 38 plugins (took 28ms)" loc="agent/agent.go(179)" logger=agent +======================================================================================================================+ | #0 - NB Transaction DownstreamResync | +======================================================================================================================+ * transaction arguments: - seqNum: 0 - type: NB Transaction, SB Sync o----------------------------------------------------------------------------------------------------------------------o * executed operations: x----------------------------------------------------------------------------------------------------------------------x | #0 - NB Transaction took 10.6ms | x----------------------------------------------------------------------------------------------------------------------x +======================================================================================================================+ | #1 - NB Transaction | +======================================================================================================================+ * transaction arguments: - seqNum: 1 - type: NB Transaction - values: - key: config/linux/interfaces/v2/interface/linux-veth1 val: { name:"linux-veth1" type:VETH host_if_name:"veth1" enabled:true veth: } - key: config/linux/interfaces/v2/interface/linux-veth2 val: { name:"linux-veth2" type:VETH namespace: host_if_name:"veth2" enabled:true ip_addresses:"192.168.1.2/30" veth: } - key: config/vpp/v2/interfaces/vpp-afpacket val: { name:"vpp-afpacket" type:AF_PACKET enabled:true ip_addresses:"192.168.1.1/30" afpacket: } o----------------------------------------------------------------------------------------------------------------------o * executed operations (2020-02-19 19:27:27.577 +0000 UTC -> 2020-02-19 19:27:27.577 +0000 UTC, dur: 0s): 1. CREATE [NOOP IS-PENDING]: - key: config/linux/interfaces/v2/interface/linux-veth1 - value: { name:"linux-veth1" type:VETH host_if_name:"veth1" enabled:true veth: } 2. CREATE [NOOP IS-PENDING]: - key: config/linux/interfaces/v2/interface/linux-veth2 - value: { name:"linux-veth2" type:VETH namespace: host_if_name:"veth2" enabled:true ip_addresses:"192.168.1.2/30" veth: } 3. CREATE [NOOP IS-PENDING]: - key: config/vpp/v2/interfaces/vpp-afpacket - value: { name:"vpp-afpacket" type:AF_PACKET enabled:true ip_addresses:"192.168.1.1/30" afpacket: } x----------------------------------------------------------------------------------------------------------------------x | #1 - NB Transaction took 400Âµs | x----------------------------------------------------------------------------------------------------------------------x time="2020-02-19 19:27:27.57741" level=info msg="Transaction #1 successful! (took 600Âµs)" loc="orchestrator/dispatcher.go(181)" logger=dispatcher +======================================================================================================================+ | #2 - SB Notification | +======================================================================================================================+ * transaction arguments: - seqNum: 2 - type: SB Notification - values: - key: linux/microservice/e2e-test-microservice1 val: o----------------------------------------------------------------------------------------------------------------------o * executed operations (2020-02-19 19:27:27.579 +0000 UTC -> 2020-02-19 19:27:27.685 +0000 UTC, dur: 106ms): 1. CREATE [OBTAINED]: - key: linux/microservice/e2e-test-microservice1 - value: 2. CREATE [WAS-PENDING]: - key: config/linux/interfaces/v2/interface/linux-veth2 - value: { name:"linux-veth2" type:VETH namespace: host_if_name:"veth2" enabled:true ip_addresses:"192.168.1.2/30" veth: } 3. CREATE [WAS-PENDING]: - key: config/linux/interfaces/v2/interface/linux-veth1 - value: { name:"linux-veth1" type:VETH host_if_name:"veth1" enabled:true veth: } 4. CREATE [WAS-PENDING]: - key: config/vpp/v2/interfaces/vpp-afpacket - value: { name:"vpp-afpacket" type:AF_PACKET enabled:true ip_addresses:"192.168.1.1/30" afpacket: } 5. CREATE [DERIVED]: - key: vpp/interface/vpp-afpacket/vrf/0/ip-version/v4 - value: 6. CREATE [DERIVED]: - key: vpp/interface/vpp-afpacket/address/static/192.168.1.1/30 - value: 7. CREATE [DERIVED]: - key: vpp/interface/vpp-afpacket/has-IP-address - value: 8. CREATE [PROPERTY]: - key: linux/interface/state/linux-veth1/UP - value: 9. CREATE [DERIVED]: - key: linux/interface/linux-veth2/address/static/192.168.1.2/30 - value: 10. CREATE [PROPERTY]: - key: linux/interface/state/linux-veth2/UP - value: x----------------------------------------------------------------------------------------------------------------------x | #2 - SB Notification took 106.2ms | x----------------------------------------------------------------------------------------------------------------------x time="2020-02-19 19:27:27.68502" level=info msg="Transaction 2 successful!" loc="kvscheduler/txn_process.go(402)" logger=kvscheduler +======================================================================================================================+ | #3 - SB Notification | +======================================================================================================================+ * transaction arguments: - seqNum: 3 - type: SB Notification - values: - key: vpp/interface/vpp-afpacket/link-state/DOWN val: o----------------------------------------------------------------------------------------------------------------------o * executed operations (2020-02-19 19:27:27.686 +0000 UTC -> 2020-02-19 19:27:27.686 +0000 UTC, dur: 0s): 1. CREATE [OBTAINED]: - key: vpp/interface/vpp-afpacket/link-state/DOWN - value: x----------------------------------------------------------------------------------------------------------------------x | #3 - SB Notification took 200Âµs | x----------------------------------------------------------------------------------------------------------------------x time="2020-02-19 19:27:27.68639" level=info msg="Transaction 3 successful!" loc="kvscheduler/txn_process.go(402)" logger=kvscheduler +======================================================================================================================+ | #4 - SB Notification | +======================================================================================================================+ * transaction arguments: - seqNum: 4 - type: SB Notification - values: - key: linux/interface/host-name/veth1 val: time="2020-02-19 19:27:28.13124" level=info msg="Transaction 4 successful!" loc="kvscheduler/txn_process.go(402)" logger=kvscheduler o----------------------------------------------------------------------------------------------------------------------o * executed operations (2020-02-19 19:27:28.131 +0000 UTC -> 2020-02-19 19:27:28.131 +0000 UTC, dur: 0s): 1. CREATE [OBTAINED]: - key: linux/interface/host-name/veth1 - value: x----------------------------------------------------------------------------------------------------------------------x | #4 - SB Notification took 200Âµs | x----------------------------------------------------------------------------------------------------------------------x +======================================================================================================================+ | #5 - SB Notification | +======================================================================================================================+ * transaction arguments: - seqNum: 5 - type: SB Notification - values: - key: linux/interface/host-name/veth1 val: o----------------------------------------------------------------------------------------------------------------------o * executed operations (2020-02-19 19:27:30.723 +0000 UTC -> 2020-02-19 19:27:30.723 +0000 UTC, dur: 0s): 1. DELETE [WAS-OBTAINED]: - key: linux/interface/host-name/veth1 - value: x----------------------------------------------------------------------------------------------------------------------x | #5 - SB Notification took 100Âµs | x----------------------------------------------------------------------------------------------------------------------x time="2020-02-19 19:27:30.72277" level=info msg="Transaction 5 successful!" loc="kvscheduler/txn_process.go(402)" logger=kvscheduler +======================================================================================================================+ | #6 - SB Notification | +======================================================================================================================+ * transaction arguments: - seqNum: 6 - type: SB Notification - values: - key: linux/microservice/e2e-test-microservice1 val: /usr/bin/vpp[6947]: linux_epoll_file_update:120: epoll_ctl: Bad file descriptor (errno 9) time="2020-02-19 19:27:30.75809" level=info msg="Signal terminated received, stopping." loc="agent/agent.go(196)" logger=agent time="2020-02-19 19:27:30.75818" level=info msg="Stopping agent" loc="agent/agent.go(269)" logger=agent time="2020-02-19 19:27:31.75149" level=error msg="failed to remove interface vpp-afpacket, index 1: no reply received within the timeout period 1s" loc="descriptor/interface_crud.go(306)" logger=vpp-ifplugin.if-descriptor time="2020-02-19 19:27:31.75181" level=error msg="LinkByName \"veth1\": Link not found" loc="descriptor/interface_veth.go(115)" logger=linux-ifplugin.if-descriptor time="2020-02-19 19:27:31.75200" level=error msg="switch to namespace failed:Microservice 'e2e-test-microservice1' is not available" loc="descriptor/interface.go(416)" logger=linux-ifplugin.if-descriptor time="2020-02-19 19:27:31.75289" level=error msg="failed to retrieve values: failed to dump memif socket details: not connected to VPP, ignoring the request" descriptor=vpp-interface loc="kvscheduler/refresh.go(121)" logger=kvscheduler time="2020-02-19 19:27:31.75386" level=error msg="KeyErrors: [config/vpp/v2/interfaces/vpp-afpacket (DELETE): failed to remove interface vpp-afpacket, index 1: no reply received within the timeout period 1s, config/linux/interfaces/v2/interface/linux-veth1 (DELETE): LinkByName \"veth1\": Link not found, config/linux/interfaces/v2/interface/linux-veth2 (DELETE): Microservice 'e2e-test-microservice1' is not available]" loc="kvscheduler/txn_process.go(404)" logger=kvscheduler time="2020-02-19 19:27:31.75409" level=info msg="Agent stopped" loc="agent/agent.go(291)" logger=agent o----------------------------------------------------------------------------------------------------------------------o * executed operations (2020-02-19 19:27:30.751 +0000 UTC -> 2020-02-19 19:27:31.752 +0000 UTC, dur: 1.002s): 1. DELETE [DERIVED]: - key: linux/interface/linux-veth2/address/static/192.168.1.2/30 - value: 2. DELETE [PROPERTY]: - key: linux/interface/state/linux-veth2/UP - value: 3. DELETE [PROPERTY]: - key: linux/interface/state/linux-veth1/UP - value: 4. DELETE [DERIVED]: - key: vpp/interface/vpp-afpacket/has-IP-address - value: 5. DELETE [DERIVED]: - key: vpp/interface/vpp-afpacket/address/static/192.168.1.1/30 - value: 6. DELETE [DERIVED]: - key: vpp/interface/vpp-afpacket/vrf/0/ip-version/v4 - value: 7. DELETE: - key: config/vpp/v2/interfaces/vpp-afpacket - value: { name:"vpp-afpacket" type:AF_PACKET enabled:true ip_addresses:"192.168.1.1/30" afpacket: } - error: failed to remove interface vpp-afpacket, index 1: no reply received within the timeout period 1s 8. DELETE: - key: config/linux/interfaces/v2/interface/linux-veth1 - value: { name:"linux-veth1" type:VETH host_if_name:"veth1" enabled:true veth: } - error: LinkByName "veth1": Link not found 9. DELETE: - key: config/linux/interfaces/v2/interface/linux-veth2 - value: { name:"linux-veth2" type:VETH namespace: host_if_name:"veth2" enabled:true ip_addresses:"192.168.1.2/30" veth: } - error: Microservice 'e2e-test-microservice1' is not available 10. DELETE [WAS-OBTAINED]: - key: linux/microservice/e2e-test-microservice1 - value: x----------------------------------------------------------------------------------------------------------------------x | #6 - SB Notification took 1.0016s | x----------------------------------------------------------------------------------------------------------------------x time="2020-02-19T19:27:31Z" level=error msg="processing request failed: not connected to VPP, ignoring the request" +======================================================================================================================+ | GRAPH 21 nodes | +======================================================================================================================+ | [linux-interface] config/linux/interfaces/v2/interface/linux-veth1 (linux-veth1) TXN-6 RETRYING | | name: "linux-veth1" | | type: VETH | | host_if_name: "veth1" | | enabled: true | | veth: < | | peer_if_name: "linux-veth2" | | > | | Depends on: | | - veth-peer-exists -> config/linux/interfaces/v2/interface/linux-veth2 | | Derives: | | - linux/interface/state/linux-veth1/UP | | Dependency for: | | - [vpp-interface] config/vpp/v2/interfaces/vpp-afpacket | | - [linux-interface] config/linux/interfaces/v2/interface/linux-veth2 | | Errors: LinkByName "veth1": Link not found | +----------------------------------------------------------------------------------------------------------------------+ | [linux-interface] config/linux/interfaces/v2/interface/linux-veth2 (linux-veth2) TXN-6 RETRYING | | name: "linux-veth2" | | type: VETH | | namespace: < | | type: MICROSERVICE | | reference: "e2e-test-microservice1" | | > | | host_if_name: "veth2" | | enabled: true | | ip_addresses: "192.168.1.2/30" | | veth: < | | peer_if_name: "linux-veth1" | | > | | Depends on: | | - microservice-available -> linux/microservice/e2e-test-microservice1 | | - veth-peer-exists -> config/linux/interfaces/v2/interface/linux-veth1 | | Derives: | | - linux/interface/linux-veth2/address/static/192.168.1.2/30 | | - linux/interface/state/linux-veth2/UP | | Dependency for: | | - [linux-interface] config/linux/interfaces/v2/interface/linux-veth1 | | Errors: Microservice 'e2e-test-microservice1' is not available | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-nat44-global] config/vpp/nat/v2/nat44-global TXN-0 OBTAINED | | virtual_reassembly: < | | timeout: 2 | | max_reassemblies: 1024 | | max_fragments: 5 | | > | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-interface] config/vpp/v2/interfaces/UNTAGGED-local0 (UNTAGGED-local0) TXN-0 OBTAINED | | name: "UNTAGGED-local0" | | type: SOFTWARE_LOOPBACK | | Metadata: &{SwIfIndex:0 Vrf:0 IPAddresses:[] TAPHostIfName:} | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-interface] config/vpp/v2/interfaces/vpp-afpacket (vpp-afpacket) TXN-6 RETRYING | | name: "vpp-afpacket" | | type: AF_PACKET | | enabled: true | | ip_addresses: "192.168.1.1/30" | | afpacket: < | | linux_interface: "linux-veth1" | | > | | Depends on: | | - afpacket-host-interface-exists -> config/linux/interfaces/v2/interface/linux-veth1 | | Derives: | | - vpp/interface/vpp-afpacket/address/static/192.168.1.1/30 | | - vpp/interface/vpp-afpacket/has-IP-address | | - vpp/interface/vpp-afpacket/vrf/0/ip-version/v4 | | Metadata: &{SwIfIndex:1 Vrf:0 IPAddresses:[192.168.1.1/30] TAPHostIfName:} | | Errors: failed to remove interface vpp-afpacket, index 1: no reply received within the timeout period 1s | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-ip-scan-neighbor] config/vpp/v2/ipscanneigh-global TXN-0 OBTAINED | | scan_interval: 1 | | max_proc_time: 20 | | max_update: 10 | | scan_int_delay: 1 | | stale_threshold: 4 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-proxy-arp] config/vpp/v2/proxyarp-global TXN-0 OBTAINED | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/0.0.0.0/0/gw/0.0.0.0 TXN-0 OBTAINED | | type: DROP | | dst_network: "0.0.0.0/0" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/0.0.0.0/32/gw/0.0.0.0 TXN-0 OBTAINED | | type: DROP | | dst_network: "0.0.0.0/32" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/224.0.0.0/4/gw/0.0.0.0 TXN-0 OBTAINED | | type: DROP | | dst_network: "224.0.0.0/4" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/240.0.0.0/4/gw/0.0.0.0 TXN-0 OBTAINED | | type: DROP | | dst_network: "240.0.0.0/4" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/255.255.255.255/32/gw/0.0.0.0 TXN-0 OBTAINED | | type: DROP | | dst_network: "255.255.255.255/32" | | next_hop_addr: "0.0.0.0" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/::/0/gw/:: TXN-0 OBTAINED | | type: DROP | | dst_network: "::/0" | | next_hop_addr: "::" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-route] config/vpp/v2/route/vrf/0/dst/fe80::/10/gw/:: TXN-0 OBTAINED | | dst_network: "fe80::/10" | | next_hop_addr: "::" | | weight: 1 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-vrf-table] config/vpp/v2/vrf-table/id/0/protocol/IPV4 (id/0/protocol/IPV4) TXN-0 OBTAINED | | label: "ipv4-VRF:0" | | Metadata: &{Index:0 Protocol:IPV4} | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-vrf-table] config/vpp/v2/vrf-table/id/0/protocol/IPV6 (id/0/protocol/IPV6) TXN-0 OBTAINED | | protocol: IPV6 | | label: "ipv6-VRF:0" | | Metadata: &{Index:0 Protocol:IPV6} | +----------------------------------------------------------------------------------------------------------------------+ | [linux-interface-watcher] linux/interface/host-name/eth0 TXN-0 OBTAINED | +----------------------------------------------------------------------------------------------------------------------+ | [linux-interface-watcher] linux/interface/host-name/lo TXN-0 OBTAINED | +----------------------------------------------------------------------------------------------------------------------+ | [microservice] linux/microservice/e2e-test-microservice1 TXN-6 REMOVED | | Dependency for: | | - [linux-interface] config/linux/interfaces/v2/interface/linux-veth2 | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-interface-link-state] vpp/interface/UNTAGGED-local0/link-state/DOWN TXN-0 OBTAINED | +----------------------------------------------------------------------------------------------------------------------+ | [vpp-interface-link-state] vpp/interface/vpp-afpacket/link-state/DOWN TXN-3 OBTAINED | +======================================================================================================================+ PASS coverage: 27.5% of statements in go.ligato.io/vpp-agent/v3/... /usr/bin/vpp[6947]: received SIGTERM, exiting... /usr/bin/vpp[6947]: unix_signal_handler:186: received signal SIGTERM, PC 0x7f167657099d --- FAIL: TestAfPacketWithLogicalReference (5.11s) e2e_test.go:613: VPP start OK (PID: 6947) e2e_test.go:157: Using docker client endpoint: unix:///var/run/docker.sock e2e_test.go:613: VPP-Agent start OK (PID: 6948) e2e_test.go:565: agent ready, took 101.119373ms 010_interfaces_test.go:339: Expected : 7 to equal : 4 e2e_test.go:209: ----------------- e2e_test.go:634: VPP-Agent exit OK e2e_test.go:634: VPP exit OK ```

Link to Travis job: https://travis-ci.com/ligato/vpp-agent/jobs/289003830#L4644

ligato / vpp-agent

Occasional e2e test failures #1592