Created
January 22, 2019 13:35
-
-
Save edwarnicke/a4545938f1a6ccefb7042423badac6d1 to your computer and use it in GitHub Desktop.
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| 2019-01-22 09:41:40,635 CRIT Supervisor running as root (no user in config file) | |
| 2019-01-22 09:41:40,638 INFO supervisord started with pid 14436 | |
| 2019-01-22 09:41:41,639 INFO spawned: 'vpp_or_agent_not_running' with pid 14455 | |
| 2019-01-22 09:41:41,640 INFO spawned: 'vpp' with pid 14456 | |
| 2019-01-22 09:41:41,642 INFO spawned: 'agent' with pid 14457 | |
| 2019-01-22 09:41:41,643 INFO spawned: 'vppagent-dataplane' with pid 14458 | |
| 2019-01-22 09:41:41,649 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T09:41:41Z" level=info msg="Using Jaeger host/port: 10.106.95.21:SRC6831" | |
| 2019-01-22 09:41:41,649 INFO success: agent entered RUNNING state, process has stayed up for > than 0 seconds (startsecs) | |
| 2019-01-22 09:41:41,649 INFO success: vppagent-dataplane entered RUNNING state, process has stayed up for > than 0 seconds (startsecs) | |
| 2019-01-22 09:41:41,651 DEBG 'vppagent-dataplane' stdout output: | |
| 2019/01/22 09:41:41 Initializing logging reporter | |
| 2019-01-22 09:41:41,655 DEBG 'vpp_or_agent_not_running' stdout output: | |
| READY | |
| 2019-01-22 09:41:41,655 DEBG vpp_or_agent_not_running: ACKNOWLEDGED -> READY | |
| 2019-01-22 09:41:41,657 DEBG 'agent' stdout output: | |
| Starting vpp-agent.. | |
| 2019-01-22 09:41:41,661 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T09:41:41Z" level=info msg="Starting vppagent-dataplane" | |
| time="2019-01-22T09:41:41Z" level=info msg="NSM_BASEDIR not set, using default /var/lib/networkservicemesh/" | |
| time="2019-01-22T09:41:41Z" level=info msg="nsmBaseDir: /var/lib/networkservicemesh/" | |
| time="2019-01-22T09:41:41Z" level=info msg="DATAPLANE_REGISTRAR_SOCKET not set, using default /var/lib/networkservicemesh/nsm.dataplane-registrar.io.sock" | |
| time="2019-01-22T09:41:41Z" level=info msg="dataplaneRegistrarSocket: /var/lib/networkservicemesh/nsm.dataplane-registrar.io.sock" | |
| time="2019-01-22T09:41:41Z" level=info msg="DATAPLANE_SOCKET not set, using default /var/lib/networkservicemesh/nsm-vppagent.dataplane.sock" | |
| time="2019-01-22T09:41:41Z" level=info msg="dataplaneSocket: /var/lib/networkservicemesh/nsm-vppagent.dataplane.sock" | |
| time="2019-01-22T09:41:41Z" level=info msg="VPPAGENT_ENDPOINT not set, using default localhost:9111" | |
| time="2019-01-22T09:41:41Z" level=info msg="vppAgentEndpoint: localhost:9111" | |
| time="2019-01-22T09:41:41Z" level=info msg="DATAPLANE_NAME not set, using default vppagent" | |
| 2019-01-22 09:41:41,661 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T09:41:41Z" level=info msg="SrcIP: 10.44.0.3, IfaceName: eth0, SrcIPNet: 10.44.0.3/12" | |
| time="2019-01-22T09:41:41Z" level=info msg="dataplaneName: vppagent" | |
| 2019-01-22 09:41:41,661 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T09:41:41Z" level=info msg="Creating vppagent server" | |
| 2019-01-22 09:41:41,662 DEBG 'vpp' stdout output: | |
| vlib_plugin_early_init:361: plugin path /usr/lib/vpp_plugins | |
| 2019-01-22 09:41:41,662 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T09:41:41Z" level=info msg="Waiting for liveness probe: tcp:localhost:9111" | |
| 2019-01-22 09:41:41,663 DEBG 'vpp' stdout output: | |
| load_one_plugin:189: Loaded plugin: abf_plugin.so (ACL based Forwarding) | |
| 2019-01-22 09:41:41,667 DEBG 'vpp' stdout output: | |
| load_one_plugin:189: Loaded plugin: acl_plugin.so (Access Control Lists) | |
| 2019-01-22 09:41:41,667 DEBG 'vpp' stdout output: | |
| load_one_plugin:189: Loaded plugin: avf_plugin.so (Intel Adaptive Virtual Function (AVF) Device Plugin) | |
| 2019-01-22 09:41:41,668 DEBG 'vpp' stdout output: | |
| load_one_plugin:191: Loaded plugin: cdp_plugin.so | |
| 2019-01-22 09:41:41,673 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:41.67325" level=debug msg="using plugin logger for \"vpp-grpc\" that was already initialized" loc="logging/log_api.go(176)" logger=defaultLogger | |
| 2019-01-22 09:41:41,674 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:41.67418" level=info msg="Starting agent version: v1.8" BuildDate="2018-12-12T02:45-08:00" CommitHash=e874d7dfba888cf2e431a70f4b0fa1d9b828583e loc="agent/agent.go(129)" logger=agent | |
| 2019-01-22 09:41:41,678 DEBG 'vpp' stdout output: | |
| load_one_plugin:106: Plugin disabled: dpdk_plugin.so | |
| 2019-01-22 09:41:41,679 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:41.67900" level=info msg="Starting agent with 25 plugins" loc="agent/agent.go(199)" logger=agent | |
| 2019-01-22 09:41:41,679 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:41.67916" level=debug msg="Microservice label is set to vpp1" loc="servicelabel/plugin_impl_servicelabel.go(44)" logger=defaultLogger | |
| 2019-01-22 09:41:41,679 DEBG 'vpp' stdout output: | |
| load_one_plugin:189: Loaded plugin: flowprobe_plugin.so (Flow per Packet) | |
| 2019-01-22 09:41:41,679 DEBG 'vpp' stdout output: | |
| load_one_plugin:189: Loaded plugin: gbp_plugin.so (Group Based Policy) | |
| 2019-01-22 09:41:41,680 DEBG 'vpp' stdout output: | |
| load_one_plugin:189: Loaded plugin: gtpu_plugin.so (GTPv1-U) | |
| 2019-01-22 09:41:41,680 DEBG 'vpp' stdout output: | |
| load_one_plugin:189: Loaded plugin: igmp_plugin.so (IGMP messaging) | |
| 2019-01-22 09:41:41,680 DEBG 'vpp' stdout output: | |
| load_one_plugin:189: Loaded plugin: ila_plugin.so (Identifier-locator addressing for IPv6) | |
| 2019-01-22 09:41:41,681 DEBG 'vpp' stdout output: | |
| load_one_plugin:189: Loaded plugin: ioam_plugin.so (Inbound OAM) | |
| 2019-01-22 09:41:41,681 DEBG 'vpp' stdout output: | |
| load_one_plugin:117: Plugin disabled (default): ixge_plugin.so | |
| 2019-01-22 09:41:41,681 DEBG 'vpp' stdout output: | |
| load_one_plugin:189: Loaded plugin: l2e_plugin.so (L2 Emulation) | |
| 2019-01-22 09:41:41,682 DEBG 'vpp' stdout output: | |
| load_one_plugin:189: Loaded plugin: lacp_plugin.so (Link Aggregation Control Protocol) | |
| 2019-01-22 09:41:41,682 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:41.68234" level=info msg="ETCD config not found, skip loading this plugin" loc="etcd/plugin_impl_etcd.go(268)" logger=etcd | |
| 2019-01-22 09:41:41,682 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:41.68273" level=info msg="Consul config not found, skip loading this plugin" loc="consul/plugin.go(137)" logger=consul | |
| 2019-01-22 09:41:41,683 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:41.68289" level=info msg="Redis config not found, skip loading this plugin" loc="redis/plugin_impl_redis.go(120)" logger=redis | |
| 2019-01-22 09:41:41,683 DEBG 'vpp' stdout output: | |
| load_one_plugin:189: Loaded plugin: lb_plugin.so (Load Balancer) | |
| 2019-01-22 09:41:41,683 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:41.68313" level=info msg="Bolt config not found, skip loading this plugin" loc="bolt/plugin.go(71)" logger=bolt | |
| time="2019-01-22 09:41:41.68340" level=info msg="kafka config not found - skip loading this plugin" loc="kafka/plugin_impl_kafka.go(72)" logger=kafka | |
| 2019-01-22 09:41:41,683 DEBG 'vpp' stdout output: | |
| load_one_plugin:189: Loaded plugin: mactime_plugin.so (Time-based MAC source-address filter) | |
| 2019-01-22 09:41:41,684 DEBG 'vpp' stdout output: | |
| load_one_plugin:189: Loaded plugin: map_plugin.so (Mapping of address and port (MAP)) | |
| 2019-01-22 09:41:41,684 DEBG 'vpp' stdout output: | |
| load_one_plugin:189: Loaded plugin: memif_plugin.so (Packet Memory Interface (experimental)) | |
| 2019-01-22 09:41:41,685 DEBG 'vpp' stdout output: | |
| load_one_plugin:189: Loaded plugin: nat_plugin.so (Network Address Translation) | |
| 2019-01-22 09:41:41,686 DEBG 'vpp' stdout output: | |
| load_one_plugin:189: Loaded plugin: nsh_plugin.so (Network Service Header) | |
| 2019-01-22 09:41:41,686 DEBG 'vpp' stdout output: | |
| load_one_plugin:189: Loaded plugin: nsim_plugin.so (network delay simulator plugin) | |
| 2019-01-22 09:41:41,686 DEBG 'vpp' stdout output: | |
| load_one_plugin:189: Loaded plugin: perfmon_plugin.so (Performance monitor plugin) | |
| 2019-01-22 09:41:41,687 DEBG 'vpp' stdout output: | |
| load_one_plugin:189: Loaded plugin: pppoe_plugin.so (PPPoE) | |
| 2019-01-22 09:41:41,687 DEBG 'vpp' stdout output: | |
| load_one_plugin:189: Loaded plugin: srv6ad_plugin.so (Dynamic SRv6 proxy) | |
| 2019-01-22 09:41:41,687 DEBG 'vpp' stdout output: | |
| load_one_plugin:189: Loaded plugin: srv6am_plugin.so (Masquerading SRv6 proxy) | |
| 2019-01-22 09:41:41,688 DEBG 'vpp' stdout output: | |
| load_one_plugin:189: Loaded plugin: srv6as_plugin.so (Static SRv6 proxy) | |
| 2019-01-22 09:41:41,688 DEBG 'vpp' stdout output: | |
| load_one_plugin:189: Loaded plugin: stn_plugin.so (VPP Steals the NIC for Container integration) | |
| 2019-01-22 09:41:41,688 DEBG 'vpp' stdout output: | |
| load_one_plugin:189: Loaded plugin: svs_plugin.so (Source VRF Select) | |
| 2019-01-22 09:41:41,689 DEBG 'vpp' stdout output: | |
| load_one_plugin:189: Loaded plugin: tlsmbedtls_plugin.so (mbedtls based TLS Engine) | |
| 2019-01-22 09:41:41,689 DEBG 'vpp' stdout output: | |
| load_one_plugin:189: Loaded plugin: tlsopenssl_plugin.so (openssl based TLS Engine) | |
| 2019-01-22 09:41:41,690 DEBG 'vpp' stdout output: | |
| load_one_plugin:117: Plugin disabled (default): unittest_plugin.so | |
| 2019-01-22 09:41:41,690 DEBG 'vpp' stdout output: | |
| load_one_plugin:189: Loaded plugin: vmxnet3_plugin.so (VMWare Vmxnet3 Device Plugin) | |
| 2019-01-22 09:41:41,691 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: clib_elf_parse_file: open `linux-vdso.so.1': No such file or directory | |
| 2019-01-22 09:41:41,709 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: clib_sysfs_prealloc_hugepages:261: pre-allocating 7 additional 2048K hugepages on numa node 0 | |
| 2019-01-22 09:41:41,710 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: buffer: vlib_physmem_shared_map_create: pmalloc_map_pages: failed to mmap 7 pages at 0x7f841a400000 fd 4 numa 0 flags 0x2011: Cannot allocate memory | |
| 2019-01-22 09:41:41,710 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: buffer: falling back to non-hugepage backed buffer pool | |
| 2019-01-22 09:41:41,765 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: perfmon: No table for cpuid 906ea | |
| 2019-01-22 09:41:41,768 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: load_one_vat_plugin:67: Loaded plugin: stn_test_plugin.so | |
| 2019-01-22 09:41:41,769 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: load_one_vat_plugin:67: Loaded plugin: nsim_test_plugin.so | |
| 2019-01-22 09:41:41,769 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: load_one_vat_plugin:67: Loaded plugin: nat_test_plugin.so | |
| 2019-01-22 09:41:41,770 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: load_one_vat_plugin:67: Loaded plugin: ioam_test_plugin.so | |
| 2019-01-22 09:41:41,770 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: load_one_vat_plugin:67: Loaded plugin: cdp_test_plugin.so | |
| 2019-01-22 09:41:41,770 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: load_one_vat_plugin:67: Loaded plugin: lacp_test_plugin.so | |
| 2019-01-22 09:41:41,771 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: load_one_vat_plugin:67: Loaded plugin: vmxnet3_test_plugin.so | |
| 2019-01-22 09:41:41,771 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: load_one_vat_plugin:67: Loaded plugin: lb_test_plugin.so | |
| 2019-01-22 09:41:41,772 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: load_one_vat_plugin:67: Loaded plugin: mactime_test_plugin.so | |
| 2019-01-22 09:41:41,772 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: load_one_vat_plugin:67: Loaded plugin: flowprobe_test_plugin.so | |
| 2019-01-22 09:41:41,772 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: load_one_vat_plugin:67: Loaded plugin: avf_test_plugin.so | |
| 2019-01-22 09:41:41,772 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: load_one_vat_plugin:67: Loaded plugin: memif_test_plugin.so | |
| 2019-01-22 09:41:41,773 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: load_one_vat_plugin:67: Loaded plugin: nsh_test_plugin.so | |
| 2019-01-22 09:41:41,773 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: load_one_vat_plugin:67: Loaded plugin: dpdk_test_plugin.so | |
| 2019-01-22 09:41:41,773 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: load_one_vat_plugin:67: Loaded plugin: gtpu_test_plugin.so | |
| 2019-01-22 09:41:41,773 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: load_one_vat_plugin:67: Loaded plugin: acl_test_plugin.so | |
| 2019-01-22 09:41:41,774 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: load_one_vat_plugin:67: Loaded plugin: pppoe_test_plugin.so | |
| 2019-01-22 09:41:41,793 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:41.79368" level=info msg="Connecting to VPP took 109.693726ms" loc="govppmux/plugin_impl_govppmux.go(141)" logger=govpp | |
| 2019-01-22 09:41:41,794 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:41.79468" level=info msg="VPP version: \"19.01-rc0~394-g6b4a32de\" (Tue Dec 11 10:50:35 UTC 2018)" loc="govppmux/plugin_impl_govppmux.go(266)" logger=govpp | |
| 2019-01-22 09:41:41,796 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:41.79606" level=info msg="VPP ACL plugin version: \"1.3\"" loc="govppmux/plugin_impl_govppmux.go(274)" logger=govpp | |
| time="2019-01-22 09:41:41.79611" level=info msg="Plugin govpp: status check probe registered" loc="statuscheck/plugin_impl_statuscheck.go(137)" logger=status-check | |
| 2019-01-22 09:41:41,796 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:41.79615" level=info msg="Agent plugin state update." lastErr="<nil>" loc="statuscheck/plugin_impl_statuscheck.go(182)" logger=status-check plugin=govpp state=ok | |
| 2019-01-22 09:41:41,796 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:41.79658" level=info msg="Init Linux namespace handler" loc="linux/linuxplugin_init.go(203)" logger=linux | |
| 2019-01-22 09:41:41,864 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T09:41:41Z" level=info msg="Waiting for liveness probe: tcp:localhost:9111" | |
| 2019-01-22 09:41:41,987 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:41.98768" level=info msg="Namespace handler plugin initialized" loc="nsplugin/ns_handler.go(108)" logger=linux.ns-handler | |
| 2019-01-22 09:41:41,988 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:41.98832" level=info msg="Init Linux interface plugin" loc="linux/linuxplugin_init.go(213)" logger=linux | |
| 2019-01-22 09:41:41,988 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:41.98844" level=info msg="Linux interface configurator initialized" loc="ifplugin/interface_config.go(110)" logger=linux.if-conf | |
| 2019-01-22 09:41:41,989 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:41.98871" level=info msg="Init Linux L3 plugin" loc="linux/linuxplugin_init.go(238)" logger=linux | |
| 2019-01-22 09:41:41,989 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:41.98905" level=info msg="Resync strategy is not known, setting up the full resync" loc="vpp/plugin_impl_vpp.go(409)" logger=vpp | |
| time="2019-01-22 09:41:41.98925" level=info msg="VPP resync strategy is set to full" loc="vpp/plugin_impl_vpp.go(667)" logger=vpp | |
| 2019-01-22 09:41:41,989 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:41.98932" level=info msg="Init interface plugin" loc="vpp/plugin_impl_vpp.go(434)" logger=vpp | |
| 2019-01-22 09:41:41,989 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:41.98961" level=info msg="Initializing AF-Packet configurator" loc="ifplugin/afpacket_config.go(75)" logger=vpp.if-conf | |
| time="2019-01-22 09:41:41.98980" level=info msg="Interface configurator initialized" loc="ifplugin/interface_config.go(110)" logger=vpp.if-conf | |
| 2019-01-22 09:41:41,990 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:41.98992" level=info msg="Interface state updater initialized" loc="ifplugin/interface_state.go(122)" logger=vpp.if-state | |
| 2019-01-22 09:41:41,990 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:41.99015" level=info msg=" BFD configurator initialized" loc="ifplugin/bfd_config.go(74)" logger=vpp.bfd-conf | |
| time="2019-01-22 09:41:41.99023" level=info msg="STN configurator initialized" loc="ifplugin/stn_config.go(82)" logger=vpp.stn-conf | |
| time="2019-01-22 09:41:41.99044" level=info msg="NAT configurator initialized" loc="ifplugin/nat_config.go(113)" logger=vpp.nat-conf | |
| 2019-01-22 09:41:41,990 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:41.99047" level=info msg="Init IPSec plugin" loc="vpp/plugin_impl_vpp.go(489)" logger=vpp | |
| time="2019-01-22 09:41:41.99052" level=info msg="Init ACL plugin" loc="vpp/plugin_impl_vpp.go(502)" logger=vpp | |
| time="2019-01-22 09:41:41.99069" level=info msg="ACL configurator initialized" loc="aclplugin/acl_config.go(93)" logger=vpp.acl-plugin | |
| time="2019-01-22 09:41:41.99079" level=info msg="Init L2 plugin" loc="vpp/plugin_impl_vpp.go(516)" logger=vpp | |
| 2019-01-22 09:41:41,991 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:41.99093" level=info msg="Initializing bridge domain state updater" loc="l2plugin/bd_state.go(93)" logger=vpp.l2-bd-state | |
| time="2019-01-22 09:41:41.99127" level=info msg="L2 FIB configurator initialized" loc="l2plugin/fib_config.go(82)" logger=vpp.l2-fib-conf | |
| 2019-01-22 09:41:41,991 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:41.99142" level=info msg="L2 XConnect configurator initialized" loc="l2plugin/xconnect_config.go(65)" logger=vpp.xc-conf | |
| time="2019-01-22 09:41:41.99146" level=info msg="Init L3 plugin" loc="vpp/plugin_impl_vpp.go(562)" logger=vpp | |
| 2019-01-22 09:41:41,992 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:41.99177" level=info msg="VPP ARP configurator initialized" loc="l3plugin/arp_config.go(79)" logger=vpp.l3-arp-conf | |
| time="2019-01-22 09:41:41.99183" level=info msg="Proxy ARP configurator initialized" loc="l3plugin/arp_proxy_config.go(76)" logger=vpp.l3-proxy-arp-conf | |
| 2019-01-22 09:41:41,992 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:41.99204" level=info msg="Init L4 plugin" loc="vpp/plugin_impl_vpp.go(596)" logger=vpp | |
| time="2019-01-22 09:41:41.99208" level=info msg="Init Punt plugin" loc="vpp/plugin_impl_vpp.go(609)" logger=vpp | |
| 2019-01-22 09:41:41,993 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:41.99235" level=info msg="Punt configurator initialized" loc="puntplugin/punt_config.go(58)" logger=vpp.punt-plugin | |
| time="2019-01-22 09:41:41.99241" level=info msg="Init SR plugin" loc="vpp/plugin_impl_vpp.go(622)" logger=vpp | |
| time="2019-01-22 09:41:41.99271" level=info msg="Segment routing configurator initialized" loc="srplugin/srv6_config.go(98)" logger=vpp.sr-plugin | |
| 2019-01-22 09:41:41,993 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:41.99335" level=warning msg="grpc plugin recovered from panic, make sure plugins for persistence are loaded: map[bolt:bolt]" loc="rpc/services.go(176)" logger=vpp-grpc | |
| 2019-01-22 09:41:41,994 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:41.99413" level=info msg="Listening on http://0.0.0.0:9191" loc="rest/plugin_impl_rest.go(108)" logger=http | |
| 2019-01-22 09:41:41,994 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:41.99463" level=info msg="Resync order[]" loc="resync/plugin_impl_resync.go(105)" logger=resync | |
| 2019-01-22 09:41:41,995 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:41.99468" level=info msg="Resync took 93ns" durationInNs=93 loc="resync/plugin_impl_resync.go(122)" logger=resync | |
| 2019-01-22 09:41:41,997 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:41.99690" level=info msg="Plugin vpp: status check probe registered" loc="statuscheck/plugin_impl_statuscheck.go(137)" logger=status-check | |
| time="2019-01-22 09:41:41.99704" level=info msg="HTTP not set, skip exposing GRPC services" loc="grpc/plugin_impl_grpc.go(82)" logger=grpc | |
| 2019-01-22 09:41:41,997 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:41.99755" level=info msg="Listening GRPC on: localhost:9111" loc="grpc/plugin_impl_grpc.go(90)" logger=grpc | |
| 2019-01-22 09:41:41,998 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:41.99865" level=info msg="Starting health http-probe on port 9191" loc="probe/plugin_impl_probe.go(74)" logger=probe | |
| time="2019-01-22 09:41:41.99871" level=info msg="Unable to register prometheus-probe handler, Prometheus is nil" loc="probe/plugin_impl_probe.go(86)" logger=probe | |
| time="2019-01-22 09:41:41.99876" level=info msg="Serving /metrics on port 9191" loc="prometheus/plugin_impl_prometheus.go(87)" logger=prometheus | |
| 2019-01-22 09:41:41,999 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:41.99880" level=info msg="Serving /vpp on port 9191" loc="prometheus/plugin_impl_prometheus.go(87)" logger=prometheus | |
| time="2019-01-22 09:41:41.99888" level=info msg="Resync order[]" loc="resync/plugin_impl_resync.go(105)" logger=resync | |
| time="2019-01-22 09:41:41.99891" level=info msg="Resync took 94ns" durationInNs=94 loc="resync/plugin_impl_resync.go(122)" logger=resync | |
| time="2019-01-22 09:41:41.99894" level=info msg="Agent started with 25 plugins (took 320ms)" loc="agent/agent.go(168)" logger=agent | |
| 2019-01-22 09:41:42,066 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T09:41:42Z" level=info msg="Resetting vppagent..." | |
| 2019-01-22 09:41:42,066 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:42.06479" level=info msg="grpc: Server.Serve failed to create ServerTransport: connection error: desc = \"transport: http2Server.HandleStreams failed to receive the preface from client: EOF\"" loc="grpclog/logger.go(63)" logger=grpc.grpc-server | |
| time="2019-01-22 09:41:42.06576" level=info msg="resync the VPP Configuration begin" loc="vpp/data_resync.go(132)" logger=vpp | |
| 2019-01-22 09:41:42,096 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:42.09617" level=info msg="Agent plugin state update." lastErr="<nil>" loc="statuscheck/plugin_impl_statuscheck.go(182)" logger=status-check plugin=vpp state=ok | |
| 2019-01-22 09:41:42,097 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:42.09732" level=info msg="Interface resync done" loc="ifplugin/data_resync.go(184)" logger=vpp.if-conf | |
| 2019-01-22 09:41:42,101 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:42.10098" level=info msg="ACL resync done" loc="aclplugin/data_resync.go(78)" logger=vpp.acl-plugin | |
| 2019-01-22 09:41:42,102 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:42.10216" level=info msg="BFD authentication key resync done" loc="ifplugin/data_resync.go(320)" logger=vpp.bfd-conf | |
| 2019-01-22 09:41:42,105 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:42.10492" level=info msg="BFD session resync done" loc="ifplugin/data_resync.go(271)" logger=vpp.bfd-conf | |
| 2019-01-22 09:41:42,111 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:42.11138" level=info msg="FIB resync done" loc="l2plugin/data_resync.go(223)" logger=vpp.l2-fib-conf | |
| 2019-01-22 09:41:42,120 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:42.12026" level=info msg="Route vrf0-fe80::/10-:: unregistered" loc="l3plugin/route_config.go(299)" logger=vpp.l3-route-conf | |
| time="2019-01-22 09:41:42.12032" level=info msg="Route fe80::/10 -> :: removed" loc="l3plugin/route_config.go(302)" logger=vpp.l3-route-conf | |
| time="2019-01-22 09:41:42.12035" level=info msg="VPP ARP resync done" loc="l3plugin/data_resync.go(184)" logger=vpp.l3-arp-conf | |
| time="2019-01-22 09:41:42.12038" level=info msg="Proxy ARP interface resync done" loc="l3plugin/data_resync.go(204)" logger=vpp.l3-proxy-arp-conf | |
| time="2019-01-22 09:41:42.12040" level=info msg="Proxy ARP interface resync done" loc="l3plugin/data_resync.go(221)" logger=vpp.l3-proxy-arp-conf | |
| 2019-01-22 09:41:42,121 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:42.12145" level=info msg="IP scan neighbor set to DISABLED" loc="l3plugin/ip_neigh_config.go(71)" logger=vpp.l3-ip-neigh-conf | |
| time="2019-01-22 09:41:42.12150" level=info msg="IP scan neighbor resync done" loc="l3plugin/data_resync.go(231)" logger=vpp.l3-ip-neigh-conf | |
| 2019-01-22 09:41:42,122 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:42.12266" level=info msg="L4 features disabled" loc="l4plugin/appns_config.go(129)" logger=vpp.l4-plugin | |
| time="2019-01-22 09:41:42.12270" level=info msg="L4 features resync done." loc="l4plugin/data_resync.go(47)" logger=vpp.l4-plugin | |
| time="2019-01-22 09:41:42.12273" level=info msg="Application namespace resync done." loc="l4plugin/data_resync.go(35)" logger=vpp.l4-plugin | |
| 2019-01-22 09:41:42,134 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:42.13384" level=info msg="NAT global config modified" loc="ifplugin/nat_config.go(262)" logger=vpp.nat-conf | |
| time="2019-01-22 09:41:42.13389" level=info msg="NAT global config resync done." loc="ifplugin/data_resync.go(431)" logger=vpp.nat-conf | |
| 2019-01-22 09:41:42,141 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:42.14096" level=info msg="Segment routing resync done" loc="srplugin/data_resync.go(66)" logger=vpp.sr-plugin | |
| time="2019-01-22 09:41:42.14102" level=info msg="resync the VPP Configuration end in 75.204143ms" durationInNs=75204143 loc="vpp/data_resync.go(136)" logger=vpp | |
| time="2019-01-22 09:41:42.14116" level=info msg="resync the Linux Configuration" loc="linux/data_resync.go(50)" logger=linux | |
| time="2019-01-22 09:41:42.14132" level=info msg="Linux interface resync done" loc="ifplugin/data_resync.go(155)" logger=linux.if-conf | |
| time="2019-01-22 09:41:42.14146" level=info msg="Linux ARP resync done" loc="l3plugin/data_resync.go(43)" logger=linux.arp-conf | |
| 2019-01-22 09:41:42,142 DEBG 'vppagent-dataplane' stdout output: | |
| 2019/01/22 09:41:42 Reporting span 1d11f3e15682d124:1d11f3e15682d124:0:1 | |
| time="2019-01-22T09:41:42Z" level=info msg="Finished resetting vppagent..." | |
| 2019-01-22 09:41:42,143 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:42.14292" level=info msg="transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:9111->127.0.0.1:35826: read: connection reset by peer" loc="grpclog/logger.go(67)" logger=grpc.grpc-server | |
| time="2019-01-22 09:41:42.14307" level=info msg="transport: loopyWriter.run returning. connection error: desc = \"transport is closing\"" loc="grpclog/logger.go(55)" logger=grpc.grpc-server | |
| time="2019-01-22 09:41:42.14321" level=info msg="grpc: Server.Serve failed to create ServerTransport: connection error: desc = \"transport: http2Server.HandleStreams failed to receive the preface from client: EOF\"" loc="grpclog/logger.go(63)" logger=grpc.grpc-server | |
| 2019-01-22 09:41:42,144 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T09:41:42Z" level=info msg="Setting up Mgmt Interface Interfaces:<name:\"mgmt\" type:AF_PACKET_INTERFACE enabled:true ip_addresses:\"10.44.0.3/12\" afpacket:<host_if_name:\"eth0\" > > " | |
| 2019-01-22 09:41:42,200 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:42.20007" level=info msg="Interface mgmt configured" loc="ifplugin/interface_config.go(320)" logger=vpp.if-conf | |
| time="2019-01-22 09:41:42.20014" level=debug msg="TX Done - all events callbacks received" loc="syncbase/done.go(79)" logger=defaultLogger | |
| 2019-01-22 09:41:42,201 DEBG 'vppagent-dataplane' stdout output: | |
| 2019/01/22 09:41:42 Reporting span 62ce7721b74c5d1a:62ce7721b74c5d1a:0:1 | |
| time="2019-01-22T09:41:42Z" level=info msg="vppagent server serving" | |
| time="2019-01-22T09:41:42Z" level=info msg="Dataplane Registrar Client" | |
| time="2019-01-22T09:41:42Z" level=info msg="Registering with NetworkServiceManager" | |
| time="2019-01-22T09:41:42Z" level=info msg="Retry interval: 30s" | |
| time="2019-01-22T09:41:42Z" level=info msg="Trying to register vppagent on socket /var/lib/networkservicemesh/nsm.dataplane-registrar.io.sock" | |
| time="2019-01-22T09:41:42Z" level=info msg="vppagent: connection to dataplane registrar socket \"/var/lib/networkservicemesh/nsm.dataplane-registrar.io.sock\" succeeded." | |
| 2019-01-22 09:41:42,201 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:41:42.20063" level=info msg="transport: loopyWriter.run returning. connection error: desc = \"transport is closing\"" loc="grpclog/logger.go(55)" logger=grpc.grpc-server | |
| 2019-01-22 09:41:42,202 DEBG 'vppagent-dataplane' stdout output: | |
| 2019/01/22 09:41:42 Reporting span 456e7e2f4e04c9a8:456e7e2f4e04c9a8:0:1 | |
| time="2019-01-22T09:41:42Z" level=info msg="vppagent: send request to Dataplane Registrar: dataplane_name:\"vppagent\" dataplane_socket:\"/var/lib/networkservicemesh/nsm-vppagent.dataplane.sock\" " | |
| time="2019-01-22T09:41:42Z" level=info msg="Registered Dataplane Registrar Client" | |
| time="2019-01-22T09:41:42Z" level=info msg="Starting DataplaneRegistrarClient liveliness monitor" | |
| time="2019-01-22T09:41:42Z" level=info msg="MonitorMechanisms was called" | |
| time="2019-01-22T09:41:42Z" level=info msg="Sending MonitorMechanisms update: remote_mechanisms:<type:VXLAN parameters:<key:\"src_ip\" value:\"10.44.0.3\" > > local_mechanisms:<type:KERNEL_INTERFACE > local_mechanisms:<type:MEM_INTERFACE > " | |
| 2019-01-22 09:41:43,205 INFO success: vpp_or_agent_not_running entered RUNNING state, process has stayed up for > than 1 seconds (startsecs) | |
| 2019-01-22 09:41:43,205 INFO success: vpp entered RUNNING state, process has stayed up for > than 1 seconds (startsecs) | |
| 2019-01-22 09:43:08,467 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T09:43:08Z" level=info msg="Request(ConnectRequest) called with id:\"3\" payload:\"IP\" local_source:<id:\"3\" network_service:\"secure-intranet-connectivity\" mechanism:<type:MEM_INTERFACE parameters:<key:\"description\" value:\"Describe 2\" > parameters:<key:\"name\" value:\"2\" > parameters:<key:\"netnsInode\" value:\"4026532730\" > parameters:<key:\"socketfile\" value:\"2/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-2\" > > context:<src_ip_addr:\"10.60.1.1/30\" dst_ip_addr:\"10.60.1.2/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > labels:<key:\"app\" value:\"firewall\" > > local_destination:<id:\"4\" network_service:\"secure-intranet-connectivity\" mechanism:<type:KERNEL_INTERFACE parameters:<key:\"description\" value:\"NSM Endpoint\" > parameters:<key:\"name\" value:\"nsmWtdIr3b4Y\" > parameters:<key:\"netnsInode\" value:\"4026532813\" > parameters:<key:\"socketfile\" value:\"nsmWtdIr3b4Y/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-6\" > > context:<src_ip_addr:\"10.60.1.1/30\" dst_ip_addr:\"10.60.1.2/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > > " | |
| 2019-01-22 09:43:08,468 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T09:43:08Z" level=info msg="Generated unique TempIfName: bh3ebb7gk40 len(TempIfName) 11" | |
| time="2019-01-22T09:43:08Z" level=info msg="m.GetParameters()[name]: nsmWtdIr3b4Y" | |
| time="2019-01-22T09:43:08Z" level=info msg="Found /dev/vhost-net - using tapv2" | |
| time="2019-01-22T09:43:08Z" level=info msg="Sending DataChange to vppagent: Interfaces:<name:\"SRC-3\" type:MEMORY_INTERFACE enabled:true memif:<master:true socket_filename:\"/var/lib/networkservicemesh/nsm-2/2/memif.sock\" > > Interfaces:<name:\"DST-3\" type:TAP_INTERFACE enabled:true tap:<version:2 host_if_name:\"bh3ebb7gk40\" > > XCons:<receive_interface:\"SRC-3\" transmit_interface:\"DST-3\" > XCons:<receive_interface:\"DST-3\" transmit_interface:\"SRC-3\" > StaticRoutes:<description:\"Route to 8.8.8.8/30\" dst_ip_addr:\"8.8.8.8/30\" next_hop_addr:\"10.60.1.2\" outgoing_interface:\"SRC-3\" > LinuxInterfaces:<name:\"DST-3\" description:\"NSM Endpoint\" type:AUTO_TAP enabled:true ip_addresses:\"10.60.1.2/30\" host_if_name:\"nsmWtdIr3b4Y\" namespace:<type:FILE_REF_NS filepath:\"/proc/15877/ns/net\" > tap:<temp_if_name:\"bh3ebb7gk40\" > > " | |
| 2019-01-22 09:43:08,470 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_add fd 11 private_data 1 idx 4 | |
| 2019-01-22 09:43:08,478 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:43:08.47790" level=info msg="Interface SRC-3 configured" loc="ifplugin/interface_config.go(320)" logger=vpp.if-conf | |
| 2019-01-22 09:43:08,506 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:43:08.50673" level=info msg="Interface DST-3 configured" loc="ifplugin/interface_config.go(320)" logger=vpp.if-conf | |
| 2019-01-22 09:43:08,541 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:43:08.54013" level=info msg="Linux interface DST-3 with hostIfName nsmWtdIr3b4Y configured" loc="ifplugin/interface_config.go(173)" logger=linux.if-conf | |
| 2019-01-22 09:43:08,541 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:43:08.54114" level=info msg="L2 XConnect pair SRC-3-DST-3 configured" loc="l2plugin/xconnect_config.go(126)" logger=vpp.xc-conf | |
| time="2019-01-22 09:43:08.54137" level=info msg="there is no linux tap configuration entry for interface bh3ebb7gk40" loc="ifplugin/interface_config.go(351)" logger=linux.if-conf | |
| 2019-01-22 09:43:08,542 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:43:08.54255" level=info msg="L2 XConnect pair DST-3-SRC-3 configured" loc="l2plugin/xconnect_config.go(126)" logger=vpp.xc-conf | |
| 2019-01-22 09:43:08,547 DEBG 'vppagent-dataplane' stdout output: | |
| 2019/01/22 09:43:08 Reporting span 3c32f36b30dbcde6:219c2970e89cabcb:7f5ef634d09d88c:1 | |
| time="2019-01-22T09:43:08Z" level=info msg="Request(ConnectRequest) called with id:\"3\" payload:\"IP\" local_source:<id:\"3\" network_service:\"secure-intranet-connectivity\" mechanism:<type:MEM_INTERFACE parameters:<key:\"description\" value:\"Describe 2\" > parameters:<key:\"name\" value:\"2\" > parameters:<key:\"netnsInode\" value:\"4026532730\" > parameters:<key:\"socketfile\" value:\"2/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-2\" > > context:<src_ip_addr:\"10.60.1.1/30\" dst_ip_addr:\"10.60.1.2/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > labels:<key:\"app\" value:\"firewall\" > > local_destination:<id:\"4\" network_service:\"secure-intranet-connectivity\" mechanism:<type:KERNEL_INTERFACE parameters:<key:\"description\" value:\"NSM Endpoint\" > parameters:<key:\"name\" value:\"nsmWtdIr3b4Y\" > parameters:<key:\"netnsInode\" value:\"4026532813\" > parameters:<key:\"socketfile\" value:\"nsmWtdIr3b4Y/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-6\" > > context:<src_ip_addr:\"10.60.1.1/30\" dst_ip_addr:\"10.60.1.2/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > > returning: id:\"3\" payload:\"IP\" local_source:<id:\"3\" network_service:\"secure-intranet-connectivity\" mechanism:<type:MEM_INTERFACE parameters:<key:\"description\" value:\"Describe 2\" > parameters:<key:\"name\" value:\"2\" > parameters:<key:\"netnsInode\" value:\"4026532730\" > parameters:<key:\"socketfile\" value:\"2/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-2\" > > context:<src_ip_addr:\"10.60.1.1/30\" dst_ip_addr:\"10.60.1.2/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > labels:<key:\"app\" value:\"firewall\" > > local_destination:<id:\"4\" network_service:\"secure-intranet-connectivity\" mechanism:<type:KERNEL_INTERFACE parameters:<key:\"description\" value:\"NSM Endpoint\" > parameters:<key:\"name\" value:\"nsmWtdIr3b4Y\" > parameters:<key:\"netnsInode\" value:\"4026532813\" > parameters:<key:\"socketfile\" value:\"nsmWtdIr3b4Y/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-6\" > > context:<src_ip_addr:\"10.60.1.1/30\" dst_ip_addr:\"10.60.1.2/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > > " | |
| 2019/01/22 09:43:08 Reporting span 3c32f36b30dbcde6:7f5ef634d09d88c:836cd84d424a2bc:1 | |
| 2019-01-22 09:43:08,551 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:43:08.54412" level=info msg="Route vrf0-8.8.8.8/30-10.60.1.2 registered" loc="l3plugin/route_config.go(173)" logger=vpp.l3-route-conf | |
| time="2019-01-22 09:43:08.54416" level=info msg="Route 8.8.8.8/30 -> 10.60.1.2 configured" loc="l3plugin/route_config.go(176)" logger=vpp.l3-route-conf | |
| time="2019-01-22 09:43:08.54424" level=debug msg="TX Done - all events callbacks received" loc="syncbase/done.go(79)" logger=defaultLogger | |
| time="2019-01-22 09:43:08.54655" level=info msg="transport: loopyWriter.run returning. connection error: desc = \"transport is closing\"" loc="grpclog/logger.go(55)" logger=grpc.grpc-server | |
| 2019-01-22 09:43:08,594 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T09:43:08Z" level=info msg="Request(ConnectRequest) called with id:\"1\" payload:\"IP\" remote_source:<id:\"1\" network_service:\"secure-intranet-connectivity\" mechanism:<type:VXLAN parameters:<key:\"dst_ip\" value:\"10.44.0.3\" > parameters:<key:\"src_ip\" value:\"10.32.0.5\" > parameters:<key:\"vni\" value:\"2\" > > context:<src_ip_addr:\"10.60.1.1/30\" dst_ip_addr:\"10.60.1.2/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > labels:<key:\"\" value:\"\" > source_network_service_manager_name:\"kube-master\" destination_network_service_manager_name:\"kube-worker\" network_service_endpoint_name:\"secure-intranet-connectivitypqkck\" > local_destination:<id:\"2\" network_service:\"secure-intranet-connectivity\" mechanism:<type:MEM_INTERFACE parameters:<key:\"description\" value:\"NSM Endpoint\" > parameters:<key:\"name\" value:\"nsmxgKmUIpM\" > parameters:<key:\"netnsInode\" value:\"4026532730\" > parameters:<key:\"socketfile\" value:\"nsmxgKmUIpM/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-2\" > > context:<src_ip_addr:\"10.60.1.1/30\" dst_ip_addr:\"10.60.1.2/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > > " | |
| time="2019-01-22T09:43:08Z" level=info msg="m.GetParameters()[src_ip]: 10.44.0.3" | |
| time="2019-01-22T09:43:08Z" level=info msg="m.GetParameters()[dst_ip]: 10.32.0.5" | |
| time="2019-01-22T09:43:08Z" level=info msg="m.GetParameters()[vni]: 2" | |
| time="2019-01-22T09:43:08Z" level=info msg="Sending DataChange to vppagent: Interfaces:<name:\"SRC-1\" type:VXLAN_TUNNEL enabled:true vxlan:<src_address:\"10.44.0.3\" dst_address:\"10.32.0.5\" vni:2 > > Interfaces:<name:\"DST-1\" type:MEMORY_INTERFACE enabled:true memif:<socket_filename:\"/var/lib/networkservicemesh/nsm-2/nsmxgKmUIpM/memif.sock\" > > XCons:<receive_interface:\"SRC-1\" transmit_interface:\"DST-1\" > XCons:<receive_interface:\"DST-1\" transmit_interface:\"SRC-1\" > " | |
| 2019-01-22 09:43:08,602 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:43:08.60211" level=info msg="Interface SRC-1 configured" loc="ifplugin/interface_config.go(320)" logger=vpp.if-conf | |
| 2019-01-22 09:43:08,612 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:43:08.61176" level=info msg="Interface DST-1 configured" loc="ifplugin/interface_config.go(320)" logger=vpp.if-conf | |
| 2019-01-22 09:43:08,613 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:43:08.61308" level=info msg="L2 XConnect pair SRC-1-DST-1 configured" loc="l2plugin/xconnect_config.go(126)" logger=vpp.xc-conf | |
| 2019-01-22 09:43:08,615 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:43:08.61438" level=info msg="L2 XConnect pair DST-1-SRC-1 configured" loc="l2plugin/xconnect_config.go(126)" logger=vpp.xc-conf | |
| time="2019-01-22 09:43:08.61443" level=debug msg="TX Done - all events callbacks received" loc="syncbase/done.go(79)" logger=defaultLogger | |
| 2019-01-22 09:43:08,617 DEBG 'vppagent-dataplane' stdout output: | |
| 2019/01/22 09:43:08 Reporting span 74789ce3a9515861:25a29b9382a437c0:7b5b2c30a9896d9d:1 | |
| time="2019-01-22T09:43:08Z" level=info msg="Request(ConnectRequest) called with id:\"1\" payload:\"IP\" remote_source:<id:\"1\" network_service:\"secure-intranet-connectivity\" mechanism:<type:VXLAN parameters:<key:\"dst_ip\" value:\"10.44.0.3\" > parameters:<key:\"src_ip\" value:\"10.32.0.5\" > parameters:<key:\"vni\" value:\"2\" > > context:<src_ip_addr:\"10.60.1.1/30\" dst_ip_addr:\"10.60.1.2/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > labels:<key:\"\" value:\"\" > source_network_service_manager_name:\"kube-master\" destination_network_service_manager_name:\"kube-worker\" network_service_endpoint_name:\"secure-intranet-connectivitypqkck\" > local_destination:<id:\"2\" network_service:\"secure-intranet-connectivity\" mechanism:<type:MEM_INTERFACE parameters:<key:\"description\" value:\"NSM Endpoint\" > parameters:<key:\"name\" value:\"nsmxgKmUIpM\" > parameters:<key:\"netnsInode\" value:\"4026532730\" > parameters:<key:\"socketfile\" value:\"nsmxgKmUIpM/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-2\" > > context:<src_ip_addr:\"10.60.1.1/30\" dst_ip_addr:\"10.60.1.2/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > > returning: id:\"1\" payload:\"IP\" remote_source:<id:\"1\" network_service:\"secure-intranet-connectivity\" mechanism:<type:VXLAN parameters:<key:\"dst_ip\" value:\"10.44.0.3\" > parameters:<key:\"src_ip\" value:\"10.32.0.5\" > parameters:<key:\"vni\" value:\"2\" > > context:<src_ip_addr:\"10.60.1.1/30\" dst_ip_addr:\"10.60.1.2/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > labels:<key:\"\" value:\"\" > source_network_service_manager_name:\"kube-master\" destination_network_service_manager_name:\"kube-worker\" network_service_endpoint_name:\"secure-intranet-connectivitypqkck\" > local_destination:<id:\"2\" network_service:\"secure-intranet-connectivity\" mechanism:<type:MEM_INTERFACE parameters:<key:\"description\" value:\"NSM Endpoint\" > parameters:<key:\"name\" value:\"nsmxgKmUIpM\" > parameters:<key:\"netnsInode\" value:\"4026532730\" > parameters:<key:\"socketfile\" value:\"nsmxgKmUIpM/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-2\" > > context:<src_ip_addr:\"10.60.1.1/30\" dst_ip_addr:\"10.60.1.2/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > > " | |
| 2019/01/22 09:43:08 Reporting span 74789ce3a9515861:7b5b2c30a9896d9d:74789ce3a9515861:1 | |
| 2019-01-22 09:43:08,617 DEBG 'agent' stdout output: | |
| time="2019-01-22 09:43:08.61537" level=info msg="transport: loopyWriter.run returning. connection error: desc = \"transport is closing\"" loc="grpclog/logger.go(55)" logger=grpc.grpc-server | |
| 2019-01-22 09:43:11,467 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_add fd 18 private_data 1 idx 7 | |
| 2019-01-22 09:43:11,489 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_add fd 21 private_data 65536 idx 8 | |
| 2019-01-22 09:43:11,557 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_add fd 22 private_data 1 idx 9 | |
| 2019-01-22 09:43:11,573 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_add fd 24 private_data 0 idx 10 | |
| 2019-01-22 11:19:12,157 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:12.15745" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:19:15,389 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:19:15Z" level=info msg="Request(ConnectRequest) called with id:\"7\" payload:\"IP\" local_source:<id:\"7\" network_service:\"secure-intranet-connectivity\" mechanism:<type:MEM_INTERFACE parameters:<key:\"description\" value:\"Describe 6\" > parameters:<key:\"name\" value:\"6\" > parameters:<key:\"netnsInode\" value:\"4026532730\" > parameters:<key:\"socketfile\" value:\"6/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-2\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > labels:<key:\"app\" value:\"firewall\" > > local_destination:<id:\"8\" network_service:\"secure-intranet-connectivity\" mechanism:<type:KERNEL_INTERFACE parameters:<key:\"description\" value:\"NSM Endpoint\" > parameters:<key:\"name\" value:\"nsmPNGZhqb4c\" > parameters:<key:\"netnsInode\" value:\"4026532813\" > parameters:<key:\"socketfile\" value:\"nsmPNGZhqb4c/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-6\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > > " | |
| 2019-01-22 11:19:15,393 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:19:15Z" level=info msg="Generated unique TempIfName: bh3focvgk4g len(TempIfName) 11" | |
| 2019-01-22 11:19:15,393 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:19:15Z" level=info msg="m.GetParameters()[name]: nsmPNGZhqb4c" | |
| 2019-01-22 11:19:15,394 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:19:15Z" level=info msg="Found /dev/vhost-net - using tapv2" | |
| 2019-01-22 11:19:15,394 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:19:15Z" level=info msg="Sending DataChange to vppagent: Interfaces:<name:\"SRC-7\" type:MEMORY_INTERFACE enabled:true memif:<master:true socket_filename:\"/var/lib/networkservicemesh/nsm-2/6/memif.sock\" > > Interfaces:<name:\"DST-7\" type:TAP_INTERFACE enabled:true tap:<version:2 host_if_name:\"bh3focvgk4g\" > > XCons:<receive_interface:\"SRC-7\" transmit_interface:\"DST-7\" > XCons:<receive_interface:\"DST-7\" transmit_interface:\"SRC-7\" > StaticRoutes:<description:\"Route to 8.8.8.8/30\" dst_ip_addr:\"8.8.8.8/30\" next_hop_addr:\"10.60.1.6\" outgoing_interface:\"SRC-7\" > LinuxInterfaces:<name:\"DST-7\" description:\"NSM Endpoint\" type:AUTO_TAP enabled:true ip_addresses:\"10.60.1.6/30\" host_if_name:\"nsmPNGZhqb4c\" namespace:<type:FILE_REF_NS filepath:\"/proc/15877/ns/net\" > tap:<temp_if_name:\"bh3focvgk4g\" > > " | |
| 2019-01-22 11:19:15,421 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:15.42132" level=info msg="Interface DST-7 configured" loc="ifplugin/interface_config.go(320)" logger=vpp.if-conf | |
| 2019-01-22 11:19:15,425 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_add fd 32 private_data 3 idx 13 | |
| 2019-01-22 11:19:15,431 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:15.43073" level=info msg="Interface SRC-7 configured" loc="ifplugin/interface_config.go(320)" logger=vpp.if-conf | |
| 2019-01-22 11:19:15,473 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:15.47351" level=info msg="Linux interface DST-7 with hostIfName nsmPNGZhqb4c configured" loc="ifplugin/interface_config.go(173)" logger=linux.if-conf | |
| time="2019-01-22 11:19:15.47365" level=info msg="there is no linux tap configuration entry for interface bh3focvgk4g" loc="ifplugin/interface_config.go(351)" logger=linux.if-conf | |
| 2019-01-22 11:19:15,474 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:15.47414" level=info msg="L2 XConnect pair DST-7-SRC-7 configured" loc="l2plugin/xconnect_config.go(126)" logger=vpp.xc-conf | |
| 2019-01-22 11:19:15,475 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:15.47576" level=info msg="L2 XConnect pair SRC-7-DST-7 configured" loc="l2plugin/xconnect_config.go(126)" logger=vpp.xc-conf | |
| 2019-01-22 11:19:15,478 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:15.47836" level=info msg="Route vrf0-8.8.8.8/30-10.60.1.6 registered" loc="l3plugin/route_config.go(173)" logger=vpp.l3-route-conf | |
| time="2019-01-22 11:19:15.47840" level=info msg="Route 8.8.8.8/30 -> 10.60.1.6 configured" loc="l3plugin/route_config.go(176)" logger=vpp.l3-route-conf | |
| time="2019-01-22 11:19:15.47843" level=debug msg="TX Done - all events callbacks received" loc="syncbase/done.go(79)" logger=defaultLogger | |
| 2019-01-22 11:19:15,478 DEBG 'vppagent-dataplane' stdout output: | |
| 2019/01/22 11:19:15 Reporting span da6651a86fdbb63:16c79c9c7743a4e4:3435659ad900df98:1 | |
| time="2019-01-22T11:19:15Z" level=info msg="Request(ConnectRequest) called with id:\"7\" payload:\"IP\" local_source:<id:\"7\" network_service:\"secure-intranet-connectivity\" mechanism:<type:MEM_INTERFACE parameters:<key:\"description\" value:\"Describe 6\" > parameters:<key:\"name\" value:\"6\" > parameters:<key:\"netnsInode\" value:\"4026532730\" > parameters:<key:\"socketfile\" value:\"6/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-2\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > labels:<key:\"app\" value:\"firewall\" > > local_destination:<id:\"8\" network_service:\"secure-intranet-connectivity\" mechanism:<type:KERNEL_INTERFACE parameters:<key:\"description\" value:\"NSM Endpoint\" > parameters:<key:\"name\" value:\"nsmPNGZhqb4c\" > parameters:<key:\"netnsInode\" value:\"4026532813\" > parameters:<key:\"socketfile\" value:\"nsmPNGZhqb4c/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-6\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > > returning: id:\"7\" payload:\"IP\" local_source:<id:\"7\" network_service:\"secure-intranet-connectivity\" mechanism:<type:MEM_INTERFACE parameters:<key:\"description\" value:\"Describe 6\" > parameters:<key:\"name\" value:\"6\" > parameters:<key:\"netnsInode\" value:\"4026532730\" > parameters:<key:\"socketfile\" value:\"6/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-2\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > labels:<key:\"app\" value:\"firewall\" > > local_destination:<id:\"8\" network_service:\"secure-intranet-connectivity\" mechanism:<type:KERNEL_INTERFACE parameters:<key:\"description\" value:\"NSM Endpoint\" > parameters:<key:\"name\" value:\"nsmPNGZhqb4c\" > parameters:<key:\"netnsInode\" value:\"4026532813\" > parameters:<key:\"socketfile\" value:\"nsmPNGZhqb4c/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-6\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > > " | |
| 2019/01/22 11:19:15 Reporting span da6651a86fdbb63:3435659ad900df98:6588c8d3823d03c7:1 | |
| 2019-01-22 11:19:15,480 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:15.47910" level=info msg="transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:9111->127.0.0.1:38262: read: connection reset by peer" loc="grpclog/logger.go(67)" logger=grpc.grpc-server | |
| time="2019-01-22 11:19:15.47918" level=info msg="transport: loopyWriter.run returning. connection error: desc = \"transport is closing\"" loc="grpclog/logger.go(55)" logger=grpc.grpc-server | |
| 2019-01-22 11:19:15,518 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:19:15Z" level=info msg="Request(ConnectRequest) called with id:\"5\" payload:\"IP\" remote_source:<id:\"5\" network_service:\"secure-intranet-connectivity\" mechanism:<type:VXLAN parameters:<key:\"dst_ip\" value:\"10.44.0.3\" > parameters:<key:\"src_ip\" value:\"10.32.0.5\" > parameters:<key:\"vni\" value:\"4\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > source_network_service_manager_name:\"kube-master\" destination_network_service_manager_name:\"kube-worker\" network_service_endpoint_name:\"secure-intranet-connectivitypqkck\" > local_destination:<id:\"6\" network_service:\"secure-intranet-connectivity\" mechanism:<type:MEM_INTERFACE parameters:<key:\"description\" value:\"NSM Endpoint\" > parameters:<key:\"name\" value:\"nsmKBgNxUG2M\" > parameters:<key:\"netnsInode\" value:\"4026532730\" > parameters:<key:\"socketfile\" value:\"nsmKBgNxUG2M/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-2\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > > " | |
| time="2019-01-22T11:19:15Z" level=info msg="m.GetParameters()[src_ip]: 10.44.0.3" | |
| time="2019-01-22T11:19:15Z" level=info msg="m.GetParameters()[dst_ip]: 10.32.0.5" | |
| time="2019-01-22T11:19:15Z" level=info msg="m.GetParameters()[vni]: 4" | |
| time="2019-01-22T11:19:15Z" level=info msg="Sending DataChange to vppagent: Interfaces:<name:\"SRC-5\" type:VXLAN_TUNNEL enabled:true vxlan:<src_address:\"10.44.0.3\" dst_address:\"10.32.0.5\" vni:4 > > Interfaces:<name:\"DST-5\" type:MEMORY_INTERFACE enabled:true memif:<socket_filename:\"/var/lib/networkservicemesh/nsm-2/nsmKBgNxUG2M/memif.sock\" > > XCons:<receive_interface:\"SRC-5\" transmit_interface:\"DST-5\" > XCons:<receive_interface:\"DST-5\" transmit_interface:\"SRC-5\" > " | |
| 2019-01-22 11:19:15,529 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:15.52913" level=info msg="Interface DST-5 configured" loc="ifplugin/interface_config.go(320)" logger=vpp.if-conf | |
| 2019-01-22 11:19:15,539 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:15.53893" level=info msg="Interface SRC-5 configured" loc="ifplugin/interface_config.go(320)" logger=vpp.if-conf | |
| 2019-01-22 11:19:15,540 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:15.54040" level=info msg="L2 XConnect pair DST-5-SRC-5 configured" loc="l2plugin/xconnect_config.go(126)" logger=vpp.xc-conf | |
| 2019-01-22 11:19:15,542 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:15.54198" level=info msg="L2 XConnect pair SRC-5-DST-5 configured" loc="l2plugin/xconnect_config.go(126)" logger=vpp.xc-conf | |
| time="2019-01-22 11:19:15.54204" level=debug msg="TX Done - all events callbacks received" loc="syncbase/done.go(79)" logger=defaultLogger | |
| 2019-01-22 11:19:15,543 DEBG 'vppagent-dataplane' stdout output: | |
| 2019/01/22 11:19:15 Reporting span 10b674da396bf828:5fe7e9a8ab0def7d:6a177a6dc2722838:1 | |
| time="2019-01-22T11:19:15Z" level=info msg="Request(ConnectRequest) called with id:\"5\" payload:\"IP\" remote_source:<id:\"5\" network_service:\"secure-intranet-connectivity\" mechanism:<type:VXLAN parameters:<key:\"dst_ip\" value:\"10.44.0.3\" > parameters:<key:\"src_ip\" value:\"10.32.0.5\" > parameters:<key:\"vni\" value:\"4\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > source_network_service_manager_name:\"kube-master\" destination_network_service_manager_name:\"kube-worker\" network_service_endpoint_name:\"secure-intranet-connectivitypqkck\" > local_destination:<id:\"6\" network_service:\"secure-intranet-connectivity\" mechanism:<type:MEM_INTERFACE parameters:<key:\"description\" value:\"NSM Endpoint\" > parameters:<key:\"name\" value:\"nsmKBgNxUG2M\" > parameters:<key:\"netnsInode\" value:\"4026532730\" > parameters:<key:\"socketfile\" value:\"nsmKBgNxUG2M/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-2\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > > returning: id:\"5\" payload:\"IP\" remote_source:<id:\"5\" network_service:\"secure-intranet-connectivity\" mechanism:<type:VXLAN parameters:<key:\"dst_ip\" value:\"10.44.0.3\" > parameters:<key:\"src_ip\" value:\"10.32.0.5\" > parameters:<key:\"vni\" value:\"4\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > source_network_service_manager_name:\"kube-master\" destination_network_service_manager_name:\"kube-worker\" network_service_endpoint_name:\"secure-intranet-connectivitypqkck\" > local_destination:<id:\"6\" network_service:\"secure-intranet-connectivity\" mechanism:<type:MEM_INTERFACE parameters:<key:\"description\" value:\"NSM Endpoint\" > parameters:<key:\"name\" value:\"nsmKBgNxUG2M\" > parameters:<key:\"netnsInode\" value:\"4026532730\" > parameters:<key:\"socketfile\" value:\"nsmKBgNxUG2M/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-2\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > > " | |
| 2019/01/22 11:19:15 Reporting span 10b674da396bf828:6a177a6dc2722838:10b674da396bf828:1 | |
| 2019-01-22 11:19:15,543 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:15.54267" level=info msg="transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:9111->127.0.0.1:38272: read: connection reset by peer" loc="grpclog/logger.go(67)" logger=grpc.grpc-server | |
| time="2019-01-22 11:19:15.54294" level=info msg="transport: loopyWriter.run returning. connection error: desc = \"transport is closing\"" loc="grpclog/logger.go(55)" logger=grpc.grpc-server | |
| 2019-01-22 11:19:17,232 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_add fd 33 private_data 3 idx 14 | |
| 2019-01-22 11:19:17,252 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_add fd 36 private_data 196608 idx 15 | |
| 2019-01-22 11:19:17,283 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_add fd 37 private_data 3 idx 16 | |
| 2019-01-22 11:19:17,307 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_add fd 39 private_data 131072 idx 17 | |
| 2019-01-22 11:19:18,175 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: memif4/0: memif_msg_receive_disconnect: disconnect received | |
| 2019-01-22 11:19:18,176 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_del idx 14 | |
| 2019-01-22 11:19:18,176 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_del idx 15 | |
| 2019-01-22 11:19:18,180 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: memif3/0: memif_msg_receive_disconnect: disconnect received | |
| 2019-01-22 11:19:18,180 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_del idx 16 | |
| 2019-01-22 11:19:18,181 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_del idx 17 | |
| 2019-01-22 11:19:18,198 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:19:18Z" level=info msg="vppagent.DisconnectRequest called with &crossconnect.CrossConnect{Id:\"7\", Payload:\"IP\", Source:(*crossconnect.CrossConnect_LocalSource)(0xc00000c1a8), Destination:(*crossconnect.CrossConnect_LocalDestination)(0xc00000c1c0), XXX_NoUnkeyedLiteral:struct {}{}, XXX_unrecognized:[]uint8(nil), XXX_sizecache:0}" | |
| 2019-01-22 11:19:18,199 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:19:18Z" level=info msg="Generated unique TempIfName: bh3fodngk50 len(TempIfName) 11" | |
| 2019-01-22 11:19:18,202 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:19:18Z" level=info msg="m.GetParameters()[name]: nsmPNGZhqb4c" | |
| time="2019-01-22T11:19:18Z" level=info msg="Found /dev/vhost-net - using tapv2" | |
| time="2019-01-22T11:19:18Z" level=info msg="Sending DataChange to vppagent: Interfaces:<name:\"SRC-7\" type:MEMORY_INTERFACE enabled:true memif:<master:true socket_filename:\"/var/lib/networkservicemesh/nsm-2/6/memif.sock\" > > Interfaces:<name:\"DST-7\" type:TAP_INTERFACE enabled:true tap:<version:2 host_if_name:\"bh3fodngk50\" > > XCons:<receive_interface:\"SRC-7\" transmit_interface:\"DST-7\" > XCons:<receive_interface:\"DST-7\" transmit_interface:\"SRC-7\" > StaticRoutes:<description:\"Route to 8.8.8.8/30\" dst_ip_addr:\"8.8.8.8/30\" next_hop_addr:\"10.60.1.6\" outgoing_interface:\"SRC-7\" > LinuxInterfaces:<name:\"DST-7\" description:\"NSM Endpoint\" type:AUTO_TAP enabled:true ip_addresses:\"10.60.1.6/30\" host_if_name:\"nsmPNGZhqb4c\" namespace:<type:FILE_REF_NS filepath:\"/proc/15877/ns/net\" > tap:<temp_if_name:\"bh3fodngk50\" > > " | |
| 2019-01-22 11:19:18,236 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:18.23650" level=info msg="Interface DST-7 removed" loc="ifplugin/interface_config.go(744)" logger=vpp.if-conf | |
| time="2019-01-22 11:19:18.23661" level=info msg="Error status log for interface DST-7 cleared" loc="vpp/error_status.go(256)" logger=vpp | |
| 2019-01-22 11:19:18,241 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_del idx 13 | |
| 2019-01-22 11:19:18,244 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:18.24347" level=info msg="Interface SRC-7 removed" loc="ifplugin/interface_config.go(744)" logger=vpp.if-conf | |
| time="2019-01-22 11:19:18.24362" level=info msg="Error status log for interface SRC-7 cleared" loc="vpp/error_status.go(256)" logger=vpp | |
| 2019-01-22 11:19:18,250 DEBG 'vppagent-dataplane' stdout output: | |
| 2019/01/22 11:19:18 Reporting span 7be86a9b3a6cb12e:3f7699cf33be35b1:6b1d403d29ee9431:1 | |
| time="2019-01-22T11:19:18Z" level=error msg="rpc error: code = Unknown desc = failed to rename TAP interface from nsmPNGZhqb4c to bh3focvgk4g: Link not found" | |
| time="2019-01-22T11:19:18Z" level=warning msg="rpc error: code = Unknown desc = failed to rename TAP interface from nsmPNGZhqb4c to bh3focvgk4g: Link not found" | |
| 2019/01/22 11:19:18 Reporting span 7be86a9b3a6cb12e:6b1d403d29ee9431:7be86a9b3a6cb12e:1 | |
| 2019-01-22 11:19:18,251 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:18.24580" level=error msg="failed to rename TAP interface from nsmPNGZhqb4c to bh3focvgk4g: Link not found\n/go/src/github.com/ligato/vpp-agent/plugins/linux/ifplugin/interface_config.go:688 (0xc8ec77)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/ifplugin/interface_config.go:713 (0xc8f4e0)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/ifplugin/interface_config.go:273 (0xc8a3b8)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/data_change.go:78 (0xdc37b2)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/data_change.go:41 (0xdc34ab)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/watch_events.go:78 (0xdc802f)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/watch_events.go:46 (0xdc84ac)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/watch_events.go:34 (0xdc83b4)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/watch_events.go:45 (0xdc7e33)\n/usr/local/go/src/runtime/asm_amd64.s:1333 (0x45c1b1)\n" loc="ifplugin/interface_config.go(1128)" logger=linux.if-conf | |
| time="2019-01-22 11:19:18.24594" level=info msg="Linux tap DST-7 configuration unregistered and moved to cache" loc="ifplugin/interface_config.go(1112)" logger=linux.if-conf | |
| time="2019-01-22 11:19:18.24630" level=error msg="failed to resolve unregistered VPP interface DST-7: failed to rename TAP interface from nsmPNGZhqb4c to bh3focvgk4g: Link not found\n/go/src/github.com/ligato/vpp-agent/plugins/linux/ifplugin/interface_config.go:1114 (0xc933de)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/watch_events.go:103 (0xdc829e)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/watch_events.go:61 (0xdc85ce)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/watch_events.go:34 (0xdc83b4)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/watch_events.go:60 (0xdc7b0f)\n/usr/local/go/src/runtime/asm_amd64.s:1333 (0x45c1b1)\n" loc="ifplugin/interface_config.go(1128)" logger=linux.if-conf | |
| time="2019-01-22 11:19:18.24638" level=info msg="Route vrf0-8.8.8.8/30-10.60.1.6 unregistered" loc="l3plugin/route_config.go(410)" logger=vpp.l3-route-conf | |
| time="2019-01-22 11:19:18.24648" level=debug msg="TX Done - all events callbacks received" loc="syncbase/done.go(79)" logger=defaultLogger | |
| time="2019-01-22 11:19:18.24654" level=info msg="Error status log: unknown type of prefix: vpp/config/v1/xconnect/" loc="vpp/error_status.go(262)" logger=vpp | |
| time="2019-01-22 11:19:18.24657" level=info msg="Error status log: unknown type of prefix: vpp/config/v1/xconnect/" loc="vpp/error_status.go(262)" logger=vpp | |
| time="2019-01-22 11:19:18.24658" level=info msg="Error status log: unknown type of prefix: vpp/config/v1/vrf/0/fib/8.8.8.8/30/" loc="vpp/error_status.go(262)" logger=vpp | |
| time="2019-01-22 11:19:18.24738" level=info msg="transport: loopyWriter.run returning. connection error: desc = \"transport is closing\"" loc="grpclog/logger.go(55)" logger=grpc.grpc-server | |
| 2019-01-22 11:19:18,253 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:19:18Z" level=info msg="vppagent.DisconnectRequest called with &crossconnect.CrossConnect{Id:\"5\", Payload:\"IP\", Source:(*crossconnect.CrossConnect_RemoteSource)(0xc00000c0e0), Destination:(*crossconnect.CrossConnect_LocalDestination)(0xc00000c0f8), XXX_NoUnkeyedLiteral:struct {}{}, XXX_unrecognized:[]uint8(nil), XXX_sizecache:0}" | |
| time="2019-01-22T11:19:18Z" level=info msg="m.GetParameters()[src_ip]: 10.44.0.3" | |
| time="2019-01-22T11:19:18Z" level=info msg="m.GetParameters()[dst_ip]: 10.32.0.5" | |
| time="2019-01-22T11:19:18Z" level=info msg="m.GetParameters()[vni]: 4" | |
| time="2019-01-22T11:19:18Z" level=info msg="Sending DataChange to vppagent: Interfaces:<name:\"SRC-5\" type:VXLAN_TUNNEL enabled:true vxlan:<src_address:\"10.44.0.3\" dst_address:\"10.32.0.5\" vni:4 > > Interfaces:<name:\"DST-5\" type:MEMORY_INTERFACE enabled:true memif:<socket_filename:\"/var/lib/networkservicemesh/nsm-2/nsmKBgNxUG2M/memif.sock\" > > XCons:<receive_interface:\"SRC-5\" transmit_interface:\"DST-5\" > XCons:<receive_interface:\"DST-5\" transmit_interface:\"SRC-5\" > " | |
| 2019-01-22 11:19:18,257 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:18.25770" level=info msg="Interface SRC-5 removed" loc="ifplugin/interface_config.go(744)" logger=vpp.if-conf | |
| time="2019-01-22 11:19:18.25779" level=info msg="Error status log for interface SRC-5 cleared" loc="vpp/error_status.go(256)" logger=vpp | |
| 2019-01-22 11:19:18,263 DEBG 'vppagent-dataplane' stdout output: | |
| 2019/01/22 11:19:18 Reporting span 46661aeae8d1b9f3:6f277a2c2ab04dda:7c1ac4fbc5bee636:1 | |
| 2019/01/22 11:19:18 Reporting span 46661aeae8d1b9f3:7c1ac4fbc5bee636:46661aeae8d1b9f3:1 | |
| 2019-01-22 11:19:18,264 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:18.26330" level=info msg="Interface DST-5 removed" loc="ifplugin/interface_config.go(744)" logger=vpp.if-conf | |
| time="2019-01-22 11:19:18.26335" level=info msg="Error status log for interface DST-5 cleared" loc="vpp/error_status.go(256)" logger=vpp | |
| time="2019-01-22 11:19:18.26347" level=info msg="Error status log: unknown type of prefix: vpp/config/v1/xconnect/" loc="vpp/error_status.go(262)" logger=vpp | |
| time="2019-01-22 11:19:18.26349" level=info msg="Error status log: unknown type of prefix: vpp/config/v1/xconnect/" loc="vpp/error_status.go(262)" logger=vpp | |
| time="2019-01-22 11:19:18.26351" level=debug msg="TX Done - all events callbacks received" loc="syncbase/done.go(79)" logger=defaultLogger | |
| 2019-01-22 11:19:18,264 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:18.26413" level=info msg="transport: loopyWriter.run returning. connection error: desc = \"transport is closing\"" loc="grpclog/logger.go(55)" logger=grpc.grpc-server | |
| 2019-01-22 11:19:18,374 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:19:18Z" level=info msg="Request(ConnectRequest) called with id:\"b\" payload:\"IP\" local_source:<id:\"b\" network_service:\"secure-intranet-connectivity\" mechanism:<type:MEM_INTERFACE parameters:<key:\"description\" value:\"Describe a\" > parameters:<key:\"name\" value:\"a\" > parameters:<key:\"netnsInode\" value:\"4026532730\" > parameters:<key:\"socketfile\" value:\"a/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-2\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > labels:<key:\"app\" value:\"firewall\" > > local_destination:<id:\"c\" network_service:\"secure-intranet-connectivity\" mechanism:<type:KERNEL_INTERFACE parameters:<key:\"description\" value:\"NSM Endpoint\" > parameters:<key:\"name\" value:\"nsm4mLZw3P4c\" > parameters:<key:\"netnsInode\" value:\"4026532813\" > parameters:<key:\"socketfile\" value:\"nsm4mLZw3P4c/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-6\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > > " | |
| 2019-01-22 11:19:18,376 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:19:18Z" level=info msg="Generated unique TempIfName: bh3fodngk5g len(TempIfName) 11" | |
| time="2019-01-22T11:19:18Z" level=info msg="m.GetParameters()[name]: nsm4mLZw3P4c" | |
| time="2019-01-22T11:19:18Z" level=info msg="Found /dev/vhost-net - using tapv2" | |
| time="2019-01-22T11:19:18Z" level=info msg="Sending DataChange to vppagent: Interfaces:<name:\"SRC-b\" type:MEMORY_INTERFACE enabled:true memif:<master:true socket_filename:\"/var/lib/networkservicemesh/nsm-2/a/memif.sock\" > > Interfaces:<name:\"DST-b\" type:TAP_INTERFACE enabled:true tap:<version:2 host_if_name:\"bh3fodngk5g\" > > XCons:<receive_interface:\"SRC-b\" transmit_interface:\"DST-b\" > XCons:<receive_interface:\"DST-b\" transmit_interface:\"SRC-b\" > StaticRoutes:<description:\"Route to 8.8.8.8/30\" dst_ip_addr:\"8.8.8.8/30\" next_hop_addr:\"10.60.1.6\" outgoing_interface:\"SRC-b\" > LinuxInterfaces:<name:\"DST-b\" description:\"NSM Endpoint\" type:AUTO_TAP enabled:true ip_addresses:\"10.60.1.6/30\" host_if_name:\"nsm4mLZw3P4c\" namespace:<type:FILE_REF_NS filepath:\"/proc/15877/ns/net\" > tap:<temp_if_name:\"bh3fodngk5g\" > > " | |
| 2019-01-22 11:19:18,400 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:18.40073" level=info msg="Interface DST-b configured" loc="ifplugin/interface_config.go(320)" logger=vpp.if-conf | |
| 2019-01-22 11:19:18,405 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_add fd 32 private_data 5 idx 11 | |
| 2019-01-22 11:19:18,412 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:18.41132" level=info msg="Interface SRC-b configured" loc="ifplugin/interface_config.go(320)" logger=vpp.if-conf | |
| 2019-01-22 11:19:18,448 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:18.44797" level=info msg="Linux interface DST-b with hostIfName nsm4mLZw3P4c configured" loc="ifplugin/interface_config.go(173)" logger=linux.if-conf | |
| 2019-01-22 11:19:18,448 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:18.44845" level=info msg="there is no linux tap configuration entry for interface bh3fodngk5g" loc="ifplugin/interface_config.go(351)" logger=linux.if-conf | |
| 2019-01-22 11:19:18,449 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:18.44908" level=info msg="L2 XConnect pair DST-b-SRC-b configured" loc="l2plugin/xconnect_config.go(126)" logger=vpp.xc-conf | |
| 2019-01-22 11:19:18,450 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:18.45059" level=info msg="L2 XConnect pair SRC-b-DST-b configured" loc="l2plugin/xconnect_config.go(126)" logger=vpp.xc-conf | |
| 2019-01-22 11:19:18,452 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:18.45225" level=info msg="Route vrf0-8.8.8.8/30-10.60.1.6 registered" loc="l3plugin/route_config.go(173)" logger=vpp.l3-route-conf | |
| time="2019-01-22 11:19:18.45229" level=info msg="Route 8.8.8.8/30 -> 10.60.1.6 configured" loc="l3plugin/route_config.go(176)" logger=vpp.l3-route-conf | |
| time="2019-01-22 11:19:18.45253" level=debug msg="TX Done - all events callbacks received" loc="syncbase/done.go(79)" logger=defaultLogger | |
| 2019-01-22 11:19:18,453 DEBG 'vppagent-dataplane' stdout output: | |
| 2019/01/22 11:19:18 Reporting span 25c514f7b9367209:2c96a27a9ddf0afb:1ca376df2ebd14d3:1 | |
| time="2019-01-22T11:19:18Z" level=info msg="Request(ConnectRequest) called with id:\"b\" payload:\"IP\" local_source:<id:\"b\" network_service:\"secure-intranet-connectivity\" mechanism:<type:MEM_INTERFACE parameters:<key:\"description\" value:\"Describe a\" > parameters:<key:\"name\" value:\"a\" > parameters:<key:\"netnsInode\" value:\"4026532730\" > parameters:<key:\"socketfile\" value:\"a/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-2\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > labels:<key:\"app\" value:\"firewall\" > > local_destination:<id:\"c\" network_service:\"secure-intranet-connectivity\" mechanism:<type:KERNEL_INTERFACE parameters:<key:\"description\" value:\"NSM Endpoint\" > parameters:<key:\"name\" value:\"nsm4mLZw3P4c\" > parameters:<key:\"netnsInode\" value:\"4026532813\" > parameters:<key:\"socketfile\" value:\"nsm4mLZw3P4c/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-6\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > > returning: id:\"b\" payload:\"IP\" local_source:<id:\"b\" network_service:\"secure-intranet-connectivity\" mechanism:<type:MEM_INTERFACE parameters:<key:\"description\" value:\"Describe a\" > parameters:<key:\"name\" value:\"a\" > parameters:<key:\"netnsInode\" value:\"4026532730\" > parameters:<key:\"socketfile\" value:\"a/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-2\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > labels:<key:\"app\" value:\"firewall\" > > local_destination:<id:\"c\" network_service:\"secure-intranet-connectivity\" mechanism:<type:KERNEL_INTERFACE parameters:<key:\"description\" value:\"NSM Endpoint\" > parameters:<key:\"name\" value:\"nsm4mLZw3P4c\" > parameters:<key:\"netnsInode\" value:\"4026532813\" > parameters:<key:\"socketfile\" value:\"nsm4mLZw3P4c/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-6\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > > " | |
| 2019/01/22 11:19:18 Reporting span 25c514f7b9367209:1ca376df2ebd14d3:3bcd7dd4d667ae8a:1 | |
| 2019-01-22 11:19:18,453 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:18.45357" level=info msg="transport: loopyWriter.run returning. connection error: desc = \"transport is closing\"" loc="grpclog/logger.go(55)" logger=grpc.grpc-server | |
| 2019-01-22 11:19:18,488 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:19:18Z" level=info msg="Request(ConnectRequest) called with id:\"9\" payload:\"IP\" remote_source:<id:\"9\" network_service:\"secure-intranet-connectivity\" mechanism:<type:VXLAN parameters:<key:\"dst_ip\" value:\"10.44.0.3\" > parameters:<key:\"src_ip\" value:\"10.32.0.5\" > parameters:<key:\"vni\" value:\"6\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > source_network_service_manager_name:\"kube-master\" destination_network_service_manager_name:\"kube-worker\" network_service_endpoint_name:\"secure-intranet-connectivitypqkck\" > local_destination:<id:\"a\" network_service:\"secure-intranet-connectivity\" mechanism:<type:MEM_INTERFACE parameters:<key:\"description\" value:\"NSM Endpoint\" > parameters:<key:\"name\" value:\"nsm3pNxJI2z\" > parameters:<key:\"netnsInode\" value:\"4026532730\" > parameters:<key:\"socketfile\" value:\"nsm3pNxJI2z/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-2\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > > " | |
| time="2019-01-22T11:19:18Z" level=info msg="m.GetParameters()[src_ip]: 10.44.0.3" | |
| time="2019-01-22T11:19:18Z" level=info msg="m.GetParameters()[dst_ip]: 10.32.0.5" | |
| time="2019-01-22T11:19:18Z" level=info msg="m.GetParameters()[vni]: 6" | |
| time="2019-01-22T11:19:18Z" level=info msg="Sending DataChange to vppagent: Interfaces:<name:\"SRC-9\" type:VXLAN_TUNNEL enabled:true vxlan:<src_address:\"10.44.0.3\" dst_address:\"10.32.0.5\" vni:6 > > Interfaces:<name:\"DST-9\" type:MEMORY_INTERFACE enabled:true memif:<socket_filename:\"/var/lib/networkservicemesh/nsm-2/nsm3pNxJI2z/memif.sock\" > > XCons:<receive_interface:\"SRC-9\" transmit_interface:\"DST-9\" > XCons:<receive_interface:\"DST-9\" transmit_interface:\"SRC-9\" > " | |
| 2019-01-22 11:19:18,495 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:18.49488" level=info msg="Interface SRC-9 configured" loc="ifplugin/interface_config.go(320)" logger=vpp.if-conf | |
| 2019-01-22 11:19:18,503 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:18.50296" level=info msg="Interface DST-9 configured" loc="ifplugin/interface_config.go(320)" logger=vpp.if-conf | |
| 2019-01-22 11:19:18,504 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:18.50438" level=info msg="L2 XConnect pair SRC-9-DST-9 configured" loc="l2plugin/xconnect_config.go(126)" logger=vpp.xc-conf | |
| 2019-01-22 11:19:18,505 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:18.50569" level=info msg="L2 XConnect pair DST-9-SRC-9 configured" loc="l2plugin/xconnect_config.go(126)" logger=vpp.xc-conf | |
| time="2019-01-22 11:19:18.50574" level=debug msg="TX Done - all events callbacks received" loc="syncbase/done.go(79)" logger=defaultLogger | |
| 2019-01-22 11:19:18,506 DEBG 'vppagent-dataplane' stdout output: | |
| 2019/01/22 11:19:18 Reporting span 1ac3d6aecd55b882:59373bc24cf79e5c:4cb53eff91e3bec3:1 | |
| 2019-01-22 11:19:18,507 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:19:18Z" level=info msg="Request(ConnectRequest) called with id:\"9\" payload:\"IP\" remote_source:<id:\"9\" network_service:\"secure-intranet-connectivity\" mechanism:<type:VXLAN parameters:<key:\"dst_ip\" value:\"10.44.0.3\" > parameters:<key:\"src_ip\" value:\"10.32.0.5\" > parameters:<key:\"vni\" value:\"6\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > source_network_service_manager_name:\"kube-master\" destination_network_service_manager_name:\"kube-worker\" network_service_endpoint_name:\"secure-intranet-connectivitypqkck\" > local_destination:<id:\"a\" network_service:\"secure-intranet-connectivity\" mechanism:<type:MEM_INTERFACE parameters:<key:\"description\" value:\"NSM Endpoint\" > parameters:<key:\"name\" value:\"nsm3pNxJI2z\" > parameters:<key:\"netnsInode\" value:\"4026532730\" > parameters:<key:\"socketfile\" value:\"nsm3pNxJI2z/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-2\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > > returning: id:\"9\" payload:\"IP\" remote_source:<id:\"9\" network_service:\"secure-intranet-connectivity\" mechanism:<type:VXLAN parameters:<key:\"dst_ip\" value:\"10.44.0.3\" > parameters:<key:\"src_ip\" value:\"10.32.0.5\" > parameters:<key:\"vni\" value:\"6\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > source_network_service_manager_name:\"kube-master\" destination_network_service_manager_name:\"kube-worker\" network_service_endpoint_name:\"secure-intranet-connectivitypqkck\" > local_destination:<id:\"a\" network_service:\"secure-intranet-connectivity\" mechanism:<type:MEM_INTERFACE parameters:<key:\"description\" value:\"NSM Endpoint\" > parameters:<key:\"name\" value:\"nsm3pNxJI2z\" > parameters:<key:\"netnsInode\" value:\"4026532730\" > parameters:<key:\"socketfile\" value:\"nsm3pNxJI2z/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-2\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > > " | |
| 2019/01/22 11:19:18 Reporting span 1ac3d6aecd55b882:4cb53eff91e3bec3:1ac3d6aecd55b882:1 | |
| 2019-01-22 11:19:18,508 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:18.50687" level=info msg="transport: loopyWriter.run returning. connection error: desc = \"transport is closing\"" loc="grpclog/logger.go(55)" logger=grpc.grpc-server | |
| 2019-01-22 11:19:20,229 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_add fd 33 private_data 2 idx 17 | |
| 2019-01-22 11:19:20,247 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_add fd 36 private_data 131072 idx 16 | |
| 2019-01-22 11:19:20,280 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_add fd 37 private_data 5 idx 15 | |
| 2019-01-22 11:19:20,301 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_add fd 39 private_data 196608 idx 14 | |
| 2019-01-22 11:19:21,111 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: memif6/0: memif_msg_receive_disconnect: disconnect received | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_del idx 17 | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_del idx 16 | |
| 2019-01-22 11:19:21,114 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: memif5/0: memif_msg_receive_disconnect: disconnect received | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_del idx 15 | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_del idx 14 | |
| 2019-01-22 11:19:21,127 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:19:21Z" level=info msg="vppagent.DisconnectRequest called with &crossconnect.CrossConnect{Id:\"b\", Payload:\"IP\", Source:(*crossconnect.CrossConnect_LocalSource)(0xc00000c3d0), Destination:(*crossconnect.CrossConnect_LocalDestination)(0xc00000c3e8), XXX_NoUnkeyedLiteral:struct {}{}, XXX_unrecognized:[]uint8(nil), XXX_sizecache:0}" | |
| time="2019-01-22T11:19:21Z" level=info msg="Generated unique TempIfName: bh3foefgk60 len(TempIfName) 11" | |
| time="2019-01-22T11:19:21Z" level=info msg="m.GetParameters()[name]: nsm4mLZw3P4c" | |
| time="2019-01-22T11:19:21Z" level=info msg="Found /dev/vhost-net - using tapv2" | |
| time="2019-01-22T11:19:21Z" level=info msg="Sending DataChange to vppagent: Interfaces:<name:\"SRC-b\" type:MEMORY_INTERFACE enabled:true memif:<master:true socket_filename:\"/var/lib/networkservicemesh/nsm-2/a/memif.sock\" > > Interfaces:<name:\"DST-b\" type:TAP_INTERFACE enabled:true tap:<version:2 host_if_name:\"bh3foefgk60\" > > XCons:<receive_interface:\"SRC-b\" transmit_interface:\"DST-b\" > XCons:<receive_interface:\"DST-b\" transmit_interface:\"SRC-b\" > StaticRoutes:<description:\"Route to 8.8.8.8/30\" dst_ip_addr:\"8.8.8.8/30\" next_hop_addr:\"10.60.1.6\" outgoing_interface:\"SRC-b\" > LinuxInterfaces:<name:\"DST-b\" description:\"NSM Endpoint\" type:AUTO_TAP enabled:true ip_addresses:\"10.60.1.6/30\" host_if_name:\"nsm4mLZw3P4c\" namespace:<type:FILE_REF_NS filepath:\"/proc/15877/ns/net\" > tap:<temp_if_name:\"bh3foefgk60\" > > " | |
| 2019-01-22 11:19:21,132 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_del idx 11 | |
| 2019-01-22 11:19:21,134 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:21.13368" level=info msg="Interface SRC-b removed" loc="ifplugin/interface_config.go(744)" logger=vpp.if-conf | |
| 2019-01-22 11:19:21,134 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:21.13389" level=info msg="Error status log for interface SRC-b cleared" loc="vpp/error_status.go(256)" logger=vpp | |
| 2019-01-22 11:19:21,169 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:21.16878" level=info msg="Interface DST-b removed" loc="ifplugin/interface_config.go(744)" logger=vpp.if-conf | |
| time="2019-01-22 11:19:21.16884" level=info msg="Error status log for interface DST-b cleared" loc="vpp/error_status.go(256)" logger=vpp | |
| 2019-01-22 11:19:21,169 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:21.16937" level=error msg="failed to rename TAP interface from nsm4mLZw3P4c to bh3fodngk5g: Link not found\n/go/src/github.com/ligato/vpp-agent/plugins/linux/ifplugin/interface_config.go:688 (0xc8ec77)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/ifplugin/interface_config.go:713 (0xc8f4e0)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/ifplugin/interface_config.go:273 (0xc8a3b8)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/data_change.go:78 (0xdc37b2)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/data_change.go:41 (0xdc34ab)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/watch_events.go:78 (0xdc802f)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/watch_events.go:46 (0xdc84ac)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/watch_events.go:34 (0xdc83b4)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/watch_events.go:45 (0xdc7e33)\n/usr/local/go/src/runtime/asm_amd64.s:1333 (0x45c1b1)\n" loc="ifplugin/interface_config.go(1128)" logger=linux.if-conf | |
| 2019-01-22 11:19:21,169 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:21.16957" level=info msg="Route vrf0-8.8.8.8/30-10.60.1.6 unregistered" loc="l3plugin/route_config.go(410)" logger=vpp.l3-route-conf | |
| time="2019-01-22 11:19:21.16971" level=info msg="Error status log: unknown type of prefix: vpp/config/v1/xconnect/" loc="vpp/error_status.go(262)" logger=vpp | |
| time="2019-01-22 11:19:21.16974" level=info msg="Error status log: unknown type of prefix: vpp/config/v1/xconnect/" loc="vpp/error_status.go(262)" logger=vpp | |
| 2019-01-22 11:19:21,170 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:21.16982" level=info msg="Linux tap DST-b configuration unregistered and moved to cache" loc="ifplugin/interface_config.go(1112)" logger=linux.if-conf | |
| 2019-01-22 11:19:21,170 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:21.17008" level=error msg="failed to resolve unregistered VPP interface DST-b: failed to rename TAP interface from nsm4mLZw3P4c to bh3fodngk5g: Link not found\n/go/src/github.com/ligato/vpp-agent/plugins/linux/ifplugin/interface_config.go:1114 (0xc933de)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/watch_events.go:103 (0xdc829e)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/watch_events.go:61 (0xdc85ce)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/watch_events.go:34 (0xdc83b4)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/watch_events.go:60 (0xdc7b0f)\n/usr/local/go/src/runtime/asm_amd64.s:1333 (0x45c1b1)\n" loc="ifplugin/interface_config.go(1128)" logger=linux.if-conf | |
| time="2019-01-22 11:19:21.17013" level=info msg="Error status log: unknown type of prefix: vpp/config/v1/vrf/0/fib/8.8.8.8/30/" loc="vpp/error_status.go(262)" logger=vpp | |
| 2019-01-22 11:19:21,170 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:21.17026" level=debug msg="TX Done - all events callbacks received" loc="syncbase/done.go(79)" logger=defaultLogger | |
| 2019-01-22 11:19:21,171 DEBG 'vppagent-dataplane' stdout output: | |
| 2019/01/22 11:19:21 Reporting span 21c14d0e858cdf52:5dde3e8713206357:4318ef295346f0bf:1 | |
| time="2019-01-22T11:19:21Z" level=error msg="rpc error: code = Unknown desc = failed to rename TAP interface from nsm4mLZw3P4c to bh3fodngk5g: Link not found" | |
| time="2019-01-22T11:19:21Z" level=warning msg="rpc error: code = Unknown desc = failed to rename TAP interface from nsm4mLZw3P4c to bh3fodngk5g: Link not found" | |
| 2019/01/22 11:19:21 Reporting span 21c14d0e858cdf52:4318ef295346f0bf:21c14d0e858cdf52:1 | |
| 2019-01-22 11:19:21,175 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:21.17095" level=info msg="transport: loopyWriter.run returning. connection error: desc = \"transport is closing\"" loc="grpclog/logger.go(55)" logger=grpc.grpc-server | |
| 2019-01-22 11:19:21,179 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:19:21Z" level=info msg="vppagent.DisconnectRequest called with &crossconnect.CrossConnect{Id:\"9\", Payload:\"IP\", Source:(*crossconnect.CrossConnect_RemoteSource)(0xc000078270), Destination:(*crossconnect.CrossConnect_LocalDestination)(0xc000078288), XXX_NoUnkeyedLiteral:struct {}{}, XXX_unrecognized:[]uint8(nil), XXX_sizecache:0}" | |
| time="2019-01-22T11:19:21Z" level=info msg="m.GetParameters()[src_ip]: 10.44.0.3" | |
| time="2019-01-22T11:19:21Z" level=info msg="m.GetParameters()[dst_ip]: 10.32.0.5" | |
| time="2019-01-22T11:19:21Z" level=info msg="m.GetParameters()[vni]: 6" | |
| time="2019-01-22T11:19:21Z" level=info msg="Sending DataChange to vppagent: Interfaces:<name:\"SRC-9\" type:VXLAN_TUNNEL enabled:true vxlan:<src_address:\"10.44.0.3\" dst_address:\"10.32.0.5\" vni:6 > > Interfaces:<name:\"DST-9\" type:MEMORY_INTERFACE enabled:true memif:<socket_filename:\"/var/lib/networkservicemesh/nsm-2/nsm3pNxJI2z/memif.sock\" > > XCons:<receive_interface:\"SRC-9\" transmit_interface:\"DST-9\" > XCons:<receive_interface:\"DST-9\" transmit_interface:\"SRC-9\" > " | |
| 2019-01-22 11:19:21,183 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:21.18331" level=info msg="Interface SRC-9 removed" loc="ifplugin/interface_config.go(744)" logger=vpp.if-conf | |
| 2019-01-22 11:19:21,184 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:21.18348" level=info msg="Error status log for interface SRC-9 cleared" loc="vpp/error_status.go(256)" logger=vpp | |
| 2019-01-22 11:19:21,188 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:21.18721" level=info msg="Interface DST-9 removed" loc="ifplugin/interface_config.go(744)" logger=vpp.if-conf | |
| time="2019-01-22 11:19:21.18742" level=info msg="Error status log for interface DST-9 cleared" loc="vpp/error_status.go(256)" logger=vpp | |
| time="2019-01-22 11:19:21.18745" level=info msg="Error status log: unknown type of prefix: vpp/config/v1/xconnect/" loc="vpp/error_status.go(262)" logger=vpp | |
| time="2019-01-22 11:19:21.18754" level=info msg="Error status log: unknown type of prefix: vpp/config/v1/xconnect/" loc="vpp/error_status.go(262)" logger=vpp | |
| 2019-01-22 11:19:21,188 DEBG 'vppagent-dataplane' stdout output: | |
| 2019/01/22 11:19:21 Reporting span 1ece31907dfcc043:747e907ed57149cb:6f32e65fbc9dff31:1 | |
| 2019/01/22 11:19:21 Reporting span 1ece31907dfcc043:6f32e65fbc9dff31:1ece31907dfcc043:1 | |
| 2019-01-22 11:19:21,190 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:21.18758" level=debug msg="TX Done - all events callbacks received" loc="syncbase/done.go(79)" logger=defaultLogger | |
| time="2019-01-22 11:19:21.18846" level=info msg="transport: loopyWriter.run returning. connection error: desc = \"transport is closing\"" loc="grpclog/logger.go(55)" logger=grpc.grpc-server | |
| 2019-01-22 11:19:21,309 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:19:21Z" level=info msg="Request(ConnectRequest) called with id:\"f\" payload:\"IP\" local_source:<id:\"f\" network_service:\"secure-intranet-connectivity\" mechanism:<type:MEM_INTERFACE parameters:<key:\"description\" value:\"Describe e\" > parameters:<key:\"name\" value:\"e\" > parameters:<key:\"netnsInode\" value:\"4026532730\" > parameters:<key:\"socketfile\" value:\"e/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-2\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > labels:<key:\"app\" value:\"firewall\" > > local_destination:<id:\"10\" network_service:\"secure-intranet-connectivity\" mechanism:<type:KERNEL_INTERFACE parameters:<key:\"description\" value:\"NSM Endpoint\" > parameters:<key:\"name\" value:\"nsmkgjZw3b4c\" > parameters:<key:\"netnsInode\" value:\"4026532813\" > parameters:<key:\"socketfile\" value:\"nsmkgjZw3b4c/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-6\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > > " | |
| 2019-01-22 11:19:21,312 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:19:21Z" level=info msg="Generated unique TempIfName: bh3foefgk6g len(TempIfName) 11" | |
| time="2019-01-22T11:19:21Z" level=info msg="m.GetParameters()[name]: nsmkgjZw3b4c" | |
| time="2019-01-22T11:19:21Z" level=info msg="Found /dev/vhost-net - using tapv2" | |
| time="2019-01-22T11:19:21Z" level=info msg="Sending DataChange to vppagent: Interfaces:<name:\"SRC-f\" type:MEMORY_INTERFACE enabled:true memif:<master:true socket_filename:\"/var/lib/networkservicemesh/nsm-2/e/memif.sock\" > > Interfaces:<name:\"DST-f\" type:TAP_INTERFACE enabled:true tap:<version:2 host_if_name:\"bh3foefgk6g\" > > XCons:<receive_interface:\"SRC-f\" transmit_interface:\"DST-f\" > XCons:<receive_interface:\"DST-f\" transmit_interface:\"SRC-f\" > StaticRoutes:<description:\"Route to 8.8.8.8/30\" dst_ip_addr:\"8.8.8.8/30\" next_hop_addr:\"10.60.1.6\" outgoing_interface:\"SRC-f\" > LinuxInterfaces:<name:\"DST-f\" description:\"NSM Endpoint\" type:AUTO_TAP enabled:true ip_addresses:\"10.60.1.6/30\" host_if_name:\"nsmkgjZw3b4c\" namespace:<type:FILE_REF_NS filepath:\"/proc/15877/ns/net\" > tap:<temp_if_name:\"bh3foefgk6g\" > > " | |
| 2019-01-22 11:19:21,316 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_add fd 26 private_data 7 idx 12 | |
| 2019-01-22 11:19:21,322 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:21.32244" level=info msg="Interface SRC-f configured" loc="ifplugin/interface_config.go(320)" logger=vpp.if-conf | |
| 2019-01-22 11:19:21,346 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:21.34618" level=info msg="Interface DST-f configured" loc="ifplugin/interface_config.go(320)" logger=vpp.if-conf | |
| 2019-01-22 11:19:21,372 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:21.37256" level=info msg="Linux interface DST-f with hostIfName nsmkgjZw3b4c configured" loc="ifplugin/interface_config.go(173)" logger=linux.if-conf | |
| 2019-01-22 11:19:21,373 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:21.37288" level=info msg="L2 XConnect pair SRC-f-DST-f configured" loc="l2plugin/xconnect_config.go(126)" logger=vpp.xc-conf | |
| 2019-01-22 11:19:21,373 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:21.37323" level=info msg="there is no linux tap configuration entry for interface bh3foefgk6g" loc="ifplugin/interface_config.go(351)" logger=linux.if-conf | |
| 2019-01-22 11:19:21,375 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:21.37497" level=info msg="L2 XConnect pair DST-f-SRC-f configured" loc="l2plugin/xconnect_config.go(126)" logger=vpp.xc-conf | |
| 2019-01-22 11:19:21,376 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:21.37672" level=info msg="Route vrf0-8.8.8.8/30-10.60.1.6 registered" loc="l3plugin/route_config.go(173)" logger=vpp.l3-route-conf | |
| time="2019-01-22 11:19:21.37677" level=info msg="Route 8.8.8.8/30 -> 10.60.1.6 configured" loc="l3plugin/route_config.go(176)" logger=vpp.l3-route-conf | |
| time="2019-01-22 11:19:21.37682" level=debug msg="TX Done - all events callbacks received" loc="syncbase/done.go(79)" logger=defaultLogger | |
| 2019-01-22 11:19:21,377 DEBG 'vppagent-dataplane' stdout output: | |
| 2019/01/22 11:19:21 Reporting span 3b2adb5993dd643b:65ab182180d07401:594e8f070c0966f3:1 | |
| time="2019-01-22T11:19:21Z" level=info msg="Request(ConnectRequest) called with id:\"f\" payload:\"IP\" local_source:<id:\"f\" network_service:\"secure-intranet-connectivity\" mechanism:<type:MEM_INTERFACE parameters:<key:\"description\" value:\"Describe e\" > parameters:<key:\"name\" value:\"e\" > parameters:<key:\"netnsInode\" value:\"4026532730\" > parameters:<key:\"socketfile\" value:\"e/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-2\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > labels:<key:\"app\" value:\"firewall\" > > local_destination:<id:\"10\" network_service:\"secure-intranet-connectivity\" mechanism:<type:KERNEL_INTERFACE parameters:<key:\"description\" value:\"NSM Endpoint\" > parameters:<key:\"name\" value:\"nsmkgjZw3b4c\" > parameters:<key:\"netnsInode\" value:\"4026532813\" > parameters:<key:\"socketfile\" value:\"nsmkgjZw3b4c/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-6\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > > returning: id:\"f\" payload:\"IP\" local_source:<id:\"f\" network_service:\"secure-intranet-connectivity\" mechanism:<type:MEM_INTERFACE parameters:<key:\"description\" value:\"Describe e\" > parameters:<key:\"name\" value:\"e\" > parameters:<key:\"netnsInode\" value:\"4026532730\" > parameters:<key:\"socketfile\" value:\"e/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-2\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > labels:<key:\"app\" value:\"firewall\" > > local_destination:<id:\"10\" network_service:\"secure-intranet-connectivity\" mechanism:<type:KERNEL_INTERFACE parameters:<key:\"description\" value:\"NSM Endpoint\" > parameters:<key:\"name\" value:\"nsmkgjZw3b4c\" > parameters:<key:\"netnsInode\" value:\"4026532813\" > parameters:<key:\"socketfile\" value:\"nsmkgjZw3b4c/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-6\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > > " | |
| 2019/01/22 11:19:21 Reporting span 3b2adb5993dd643b:594e8f070c0966f3:6d6f43019d1b14dd:1 | |
| 2019-01-22 11:19:21,377 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:21.37748" level=info msg="transport: loopyWriter.run returning. connection error: desc = \"transport is closing\"" loc="grpclog/logger.go(55)" logger=grpc.grpc-server | |
| 2019-01-22 11:19:21,413 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:19:21Z" level=info msg="Request(ConnectRequest) called with id:\"d\" payload:\"IP\" remote_source:<id:\"d\" network_service:\"secure-intranet-connectivity\" mechanism:<type:VXLAN parameters:<key:\"dst_ip\" value:\"10.44.0.3\" > parameters:<key:\"src_ip\" value:\"10.32.0.5\" > parameters:<key:\"vni\" value:\"8\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > source_network_service_manager_name:\"kube-master\" destination_network_service_manager_name:\"kube-worker\" network_service_endpoint_name:\"secure-intranet-connectivitypqkck\" > local_destination:<id:\"e\" network_service:\"secure-intranet-connectivity\" mechanism:<type:MEM_INTERFACE parameters:<key:\"description\" value:\"NSM Endpoint\" > parameters:<key:\"name\" value:\"nsmfLhNxJGpM\" > parameters:<key:\"netnsInode\" value:\"4026532730\" > parameters:<key:\"socketfile\" value:\"nsmfLhNxJGpM/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-2\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > > " | |
| time="2019-01-22T11:19:21Z" level=info msg="m.GetParameters()[src_ip]: 10.44.0.3" | |
| time="2019-01-22T11:19:21Z" level=info msg="m.GetParameters()[dst_ip]: 10.32.0.5" | |
| time="2019-01-22T11:19:21Z" level=info msg="m.GetParameters()[vni]: 8" | |
| time="2019-01-22T11:19:21Z" level=info msg="Sending DataChange to vppagent: Interfaces:<name:\"SRC-d\" type:VXLAN_TUNNEL enabled:true vxlan:<src_address:\"10.44.0.3\" dst_address:\"10.32.0.5\" vni:8 > > Interfaces:<name:\"DST-d\" type:MEMORY_INTERFACE enabled:true memif:<socket_filename:\"/var/lib/networkservicemesh/nsm-2/nsmfLhNxJGpM/memif.sock\" > > XCons:<receive_interface:\"SRC-d\" transmit_interface:\"DST-d\" > XCons:<receive_interface:\"DST-d\" transmit_interface:\"SRC-d\" > " | |
| 2019-01-22 11:19:21,420 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:21.41987" level=info msg="Interface SRC-d configured" loc="ifplugin/interface_config.go(320)" logger=vpp.if-conf | |
| 2019-01-22 11:19:21,429 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:21.42940" level=info msg="Interface DST-d configured" loc="ifplugin/interface_config.go(320)" logger=vpp.if-conf | |
| 2019-01-22 11:19:21,430 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:21.43069" level=info msg="L2 XConnect pair SRC-d-DST-d configured" loc="l2plugin/xconnect_config.go(126)" logger=vpp.xc-conf | |
| 2019-01-22 11:19:21,432 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:21.43199" level=info msg="L2 XConnect pair DST-d-SRC-d configured" loc="l2plugin/xconnect_config.go(126)" logger=vpp.xc-conf | |
| time="2019-01-22 11:19:21.43204" level=debug msg="TX Done - all events callbacks received" loc="syncbase/done.go(79)" logger=defaultLogger | |
| 2019-01-22 11:19:21,433 DEBG 'vppagent-dataplane' stdout output: | |
| 2019/01/22 11:19:21 Reporting span 3196f8ae60a5c70e:2362de7e7342b8a:21a69f3e1542ff92:1 | |
| time="2019-01-22T11:19:21Z" level=info msg="Request(ConnectRequest) called with id:\"d\" payload:\"IP\" remote_source:<id:\"d\" network_service:\"secure-intranet-connectivity\" mechanism:<type:VXLAN parameters:<key:\"dst_ip\" value:\"10.44.0.3\" > parameters:<key:\"src_ip\" value:\"10.32.0.5\" > parameters:<key:\"vni\" value:\"8\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > source_network_service_manager_name:\"kube-master\" destination_network_service_manager_name:\"kube-worker\" network_service_endpoint_name:\"secure-intranet-connectivitypqkck\" > local_destination:<id:\"e\" network_service:\"secure-intranet-connectivity\" mechanism:<type:MEM_INTERFACE parameters:<key:\"description\" value:\"NSM Endpoint\" > parameters:<key:\"name\" value:\"nsmfLhNxJGpM\" > parameters:<key:\"netnsInode\" value:\"4026532730\" > parameters:<key:\"socketfile\" value:\"nsmfLhNxJGpM/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-2\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > > returning: id:\"d\" payload:\"IP\" remote_source:<id:\"d\" network_service:\"secure-intranet-connectivity\" mechanism:<type:VXLAN parameters:<key:\"dst_ip\" value:\"10.44.0.3\" > parameters:<key:\"src_ip\" value:\"10.32.0.5\" > parameters:<key:\"vni\" value:\"8\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > source_network_service_manager_name:\"kube-master\" destination_network_service_manager_name:\"kube-worker\" network_service_endpoint_name:\"secure-intranet-connectivitypqkck\" > local_destination:<id:\"e\" network_service:\"secure-intranet-connectivity\" mechanism:<type:MEM_INTERFACE parameters:<key:\"description\" value:\"NSM Endpoint\" > parameters:<key:\"name\" value:\"nsmfLhNxJGpM\" > parameters:<key:\"netnsInode\" value:\"4026532730\" > parameters:<key:\"socketfile\" value:\"nsmfLhNxJGpM/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-2\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > > " | |
| 2019/01/22 11:19:21 Reporting span 3196f8ae60a5c70e:21a69f3e1542ff92:3196f8ae60a5c70e:1 | |
| 2019-01-22 11:19:21,433 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:21.43287" level=info msg="transport: loopyWriter.run returning. connection error: desc = \"transport is closing\"" loc="grpclog/logger.go(55)" logger=grpc.grpc-server | |
| 2019-01-22 11:19:22,159 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:22.15926" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:19:23,225 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_add fd 33 private_data 3 idx 14 | |
| 2019-01-22 11:19:23,247 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_add fd 36 private_data 196608 idx 15 | |
| 2019-01-22 11:19:23,276 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_add fd 37 private_data 7 idx 16 | |
| 2019-01-22 11:19:23,296 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_add fd 39 private_data 131072 idx 17 | |
| 2019-01-22 11:19:24,089 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: memif7/0: memif_msg_receive_disconnect: disconnect received | |
| 2019-01-22 11:19:24,090 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_del idx 16 | |
| 2019-01-22 11:19:24,090 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_del idx 17 | |
| 2019-01-22 11:19:24,094 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: memif8/0: memif_msg_receive_disconnect: disconnect received | |
| 2019-01-22 11:19:24,094 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_del idx 14 | |
| 2019-01-22 11:19:24,095 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_del idx 15 | |
| 2019-01-22 11:19:24,106 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:19:24Z" level=info msg="vppagent.DisconnectRequest called with &crossconnect.CrossConnect{Id:\"f\", Payload:\"IP\", Source:(*crossconnect.CrossConnect_LocalSource)(0xc000078150), Destination:(*crossconnect.CrossConnect_LocalDestination)(0xc000078168), XXX_NoUnkeyedLiteral:struct {}{}, XXX_unrecognized:[]uint8(nil), XXX_sizecache:0}" | |
| 2019-01-22 11:19:24,109 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:19:24Z" level=info msg="Generated unique TempIfName: bh3fof7gk70 len(TempIfName) 11" | |
| time="2019-01-22T11:19:24Z" level=info msg="m.GetParameters()[name]: nsmkgjZw3b4c" | |
| time="2019-01-22T11:19:24Z" level=info msg="Found /dev/vhost-net - using tapv2" | |
| time="2019-01-22T11:19:24Z" level=info msg="Sending DataChange to vppagent: Interfaces:<name:\"SRC-f\" type:MEMORY_INTERFACE enabled:true memif:<master:true socket_filename:\"/var/lib/networkservicemesh/nsm-2/e/memif.sock\" > > Interfaces:<name:\"DST-f\" type:TAP_INTERFACE enabled:true tap:<version:2 host_if_name:\"bh3fof7gk70\" > > XCons:<receive_interface:\"SRC-f\" transmit_interface:\"DST-f\" > XCons:<receive_interface:\"DST-f\" transmit_interface:\"SRC-f\" > StaticRoutes:<description:\"Route to 8.8.8.8/30\" dst_ip_addr:\"8.8.8.8/30\" next_hop_addr:\"10.60.1.6\" outgoing_interface:\"SRC-f\" > LinuxInterfaces:<name:\"DST-f\" description:\"NSM Endpoint\" type:AUTO_TAP enabled:true ip_addresses:\"10.60.1.6/30\" host_if_name:\"nsmkgjZw3b4c\" namespace:<type:FILE_REF_NS filepath:\"/proc/15877/ns/net\" > tap:<temp_if_name:\"bh3fof7gk70\" > > " | |
| 2019-01-22 11:19:24,111 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_del idx 12 | |
| 2019-01-22 11:19:24,117 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:24.11510" level=info msg="Interface SRC-f removed" loc="ifplugin/interface_config.go(744)" logger=vpp.if-conf | |
| time="2019-01-22 11:19:24.11569" level=info msg="Error status log for interface SRC-f cleared" loc="vpp/error_status.go(256)" logger=vpp | |
| time="2019-01-22 11:19:24.11592" level=info msg="Route vrf0-8.8.8.8/30-10.60.1.6 unregistered" loc="l3plugin/route_config.go(410)" logger=vpp.l3-route-conf | |
| 2019-01-22 11:19:24,156 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:24.15603" level=info msg="Linux interface nsmkgjZw3b4c removed" loc="ifplugin/interface_config.go(282)" logger=linux.if-conf | |
| 2019-01-22 11:19:24,189 DEBG 'vppagent-dataplane' stdout output: | |
| 2019/01/22 11:19:24 Reporting span 285e819785dcfd0b:7c26ce46145208e6:311a86fe03c1ed22:1 | |
| 2019/01/22 11:19:24 Reporting span 285e819785dcfd0b:311a86fe03c1ed22:285e819785dcfd0b:1 | |
| 2019-01-22 11:19:24,189 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:24.18860" level=info msg="Interface DST-f removed" loc="ifplugin/interface_config.go(744)" logger=vpp.if-conf | |
| time="2019-01-22 11:19:24.18877" level=info msg="Error status log for interface DST-f cleared" loc="vpp/error_status.go(256)" logger=vpp | |
| time="2019-01-22 11:19:24.18881" level=info msg="Error status log: unknown type of prefix: vpp/config/v1/xconnect/" loc="vpp/error_status.go(262)" logger=vpp | |
| time="2019-01-22 11:19:24.18883" level=info msg="Error status log: unknown type of prefix: vpp/config/v1/xconnect/" loc="vpp/error_status.go(262)" logger=vpp | |
| time="2019-01-22 11:19:24.18884" level=info msg="Error status log: unknown type of prefix: vpp/config/v1/vrf/0/fib/8.8.8.8/30/" loc="vpp/error_status.go(262)" logger=vpp | |
| time="2019-01-22 11:19:24.18887" level=debug msg="TX Done - all events callbacks received" loc="syncbase/done.go(79)" logger=defaultLogger | |
| 2019-01-22 11:19:24,192 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:24.18989" level=info msg="transport: loopyWriter.run returning. connection error: desc = \"transport is closing\"" loc="grpclog/logger.go(55)" logger=grpc.grpc-server | |
| 2019-01-22 11:19:24,194 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:19:24Z" level=info msg="vppagent.DisconnectRequest called with &crossconnect.CrossConnect{Id:\"d\", Payload:\"IP\", Source:(*crossconnect.CrossConnect_RemoteSource)(0xc000078318), Destination:(*crossconnect.CrossConnect_LocalDestination)(0xc000078330), XXX_NoUnkeyedLiteral:struct {}{}, XXX_unrecognized:[]uint8(nil), XXX_sizecache:0}" | |
| time="2019-01-22T11:19:24Z" level=info msg="m.GetParameters()[src_ip]: 10.44.0.3" | |
| time="2019-01-22T11:19:24Z" level=info msg="m.GetParameters()[dst_ip]: 10.32.0.5" | |
| time="2019-01-22T11:19:24Z" level=info msg="m.GetParameters()[vni]: 8" | |
| 2019-01-22 11:19:24,195 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:19:24Z" level=info msg="Sending DataChange to vppagent: Interfaces:<name:\"SRC-d\" type:VXLAN_TUNNEL enabled:true vxlan:<src_address:\"10.44.0.3\" dst_address:\"10.32.0.5\" vni:8 > > Interfaces:<name:\"DST-d\" type:MEMORY_INTERFACE enabled:true memif:<socket_filename:\"/var/lib/networkservicemesh/nsm-2/nsmfLhNxJGpM/memif.sock\" > > XCons:<receive_interface:\"SRC-d\" transmit_interface:\"DST-d\" > XCons:<receive_interface:\"DST-d\" transmit_interface:\"SRC-d\" > " | |
| 2019-01-22 11:19:24,199 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:24.19953" level=info msg="Interface DST-d removed" loc="ifplugin/interface_config.go(744)" logger=vpp.if-conf | |
| 2019-01-22 11:19:24,200 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:24.19965" level=info msg="Error status log for interface DST-d cleared" loc="vpp/error_status.go(256)" logger=vpp | |
| 2019-01-22 11:19:24,203 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:24.20352" level=info msg="Interface SRC-d removed" loc="ifplugin/interface_config.go(744)" logger=vpp.if-conf | |
| 2019-01-22 11:19:24,204 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:24.20364" level=info msg="Error status log for interface SRC-d cleared" loc="vpp/error_status.go(256)" logger=vpp | |
| time="2019-01-22 11:19:24.20366" level=info msg="Error status log: unknown type of prefix: vpp/config/v1/xconnect/" loc="vpp/error_status.go(262)" logger=vpp | |
| time="2019-01-22 11:19:24.20368" level=info msg="Error status log: unknown type of prefix: vpp/config/v1/xconnect/" loc="vpp/error_status.go(262)" logger=vpp | |
| time="2019-01-22 11:19:24.20378" level=debug msg="TX Done - all events callbacks received" loc="syncbase/done.go(79)" logger=defaultLogger | |
| 2019-01-22 11:19:24,204 DEBG 'vppagent-dataplane' stdout output: | |
| 2019/01/22 11:19:24 Reporting span 9584f538a337e13:11e905bc8247ec0:72d728d0f834c282:1 | |
| 2019/01/22 11:19:24 Reporting span 9584f538a337e13:72d728d0f834c282:9584f538a337e13:1 | |
| 2019-01-22 11:19:24,205 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:24.20529" level=info msg="transport: loopyWriter.run returning. connection error: desc = \"transport is closing\"" loc="grpclog/logger.go(55)" logger=grpc.grpc-server | |
| 2019-01-22 11:19:32,153 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:32.15366" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:19:42,154 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:42.15444" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:19:52,155 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:19:52.15528" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:20:02,157 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:20:02.15718" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:20:12,163 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:20:12.16307" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:20:22,156 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:20:22.15607" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:20:32,161 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:20:32.16162" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:20:42,157 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:20:42.15690" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:20:52,156 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:20:52.15666" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:21:02,164 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:21:02.16398" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:21:12,163 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:21:12.16339" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:21:22,159 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:21:22.15915" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:21:32,165 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:21:32.16543" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:21:42,161 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:21:42.16160" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:21:52,167 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:21:52.16740" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:22:02,161 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:22:02.16142" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:22:12,167 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:22:12.16698" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:22:22,169 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:22:22.16907" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:22:32,170 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:22:32.17022" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:22:42,162 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:22:42.16278" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:22:52,170 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:22:52.17066" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:23:02,163 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:23:02.16311" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:23:12,166 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:23:12.16592" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:23:22,166 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:23:22.16635" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:23:32,168 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:23:32.16817" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:23:42,166 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:23:42.16663" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:23:52,168 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:23:52.16776" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:24:02,170 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:24:02.16991" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:24:12,169 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:24:12.16962" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:24:22,168 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:24:22.16828" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:24:32,174 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:24:32.17449" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:24:42,168 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:24:42.16830" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:24:52,176 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:24:52.17659" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:25:02,169 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:25:02.16977" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:25:12,182 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:25:12.18196" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:25:22,177 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:25:22.17696" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:25:32,173 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:25:32.17317" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:25:42,173 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:25:42.17331" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:25:52,172 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:25:52.17207" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:26:02,178 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:26:02.17794" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:26:12,173 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:26:12.17371" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:26:22,174 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:26:22.17463" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:26:32,180 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:26:32.18039" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:26:42,173 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:26:42.17383" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:26:52,181 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:26:52.18114" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:27:02,180 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:27:02.18054" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:27:12,175 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:27:12.17538" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:27:22,178 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:27:22.17822" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:27:32,186 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:27:32.18584" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:27:42,178 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:27:42.17862" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:27:52,186 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:27:52.18642" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:28:02,180 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:28:02.17995" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:28:12,180 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:28:12.17995" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:28:22,181 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:28:22.18075" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:28:32,181 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:28:32.18085" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:28:42,180 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:28:42.18048" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:28:52,182 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:28:52.18185" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:29:02,184 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:29:02.18444" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:29:12,185 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:29:12.18496" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:29:22,185 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:29:22.18532" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:29:32,185 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:29:32.18498" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:29:42,190 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:29:42.19006" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:29:52,165 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:29:52.16571" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:30:02,186 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:30:02.18589" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:30:12,183 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:30:12.18368" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:30:19,891 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:30:19Z" level=info msg="Request(ConnectRequest) called with id:\"13\" payload:\"IP\" local_source:<id:\"13\" network_service:\"secure-intranet-connectivity\" mechanism:<type:MEM_INTERFACE parameters:<key:\"description\" value:\"Describe 12\" > parameters:<key:\"name\" value:\"12\" > parameters:<key:\"netnsInode\" value:\"4026532730\" > parameters:<key:\"socketfile\" value:\"12/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-2\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > labels:<key:\"app\" value:\"firewall\" > > local_destination:<id:\"14\" network_service:\"secure-intranet-connectivity\" mechanism:<type:KERNEL_INTERFACE parameters:<key:\"description\" value:\"NSM Endpoint\" > parameters:<key:\"name\" value:\"nsmJmECU3PvY\" > parameters:<key:\"netnsInode\" value:\"4026532813\" > parameters:<key:\"socketfile\" value:\"nsmJmECU3PvY/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-6\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > > " | |
| 2019-01-22 11:30:19,894 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:30:19Z" level=info msg="Generated unique TempIfName: bh3ftivgk7g len(TempIfName) 11" | |
| time="2019-01-22T11:30:19Z" level=info msg="m.GetParameters()[name]: nsmJmECU3PvY" | |
| time="2019-01-22T11:30:19Z" level=info msg="Found /dev/vhost-net - using tapv2" | |
| 2019-01-22 11:30:19,895 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:30:19Z" level=info msg="Sending DataChange to vppagent: Interfaces:<name:\"SRC-13\" type:MEMORY_INTERFACE enabled:true memif:<master:true socket_filename:\"/var/lib/networkservicemesh/nsm-2/12/memif.sock\" > > Interfaces:<name:\"DST-13\" type:TAP_INTERFACE enabled:true tap:<version:2 host_if_name:\"bh3ftivgk7g\" > > XCons:<receive_interface:\"SRC-13\" transmit_interface:\"DST-13\" > XCons:<receive_interface:\"DST-13\" transmit_interface:\"SRC-13\" > StaticRoutes:<description:\"Route to 8.8.8.8/30\" dst_ip_addr:\"8.8.8.8/30\" next_hop_addr:\"10.60.1.6\" outgoing_interface:\"SRC-13\" > LinuxInterfaces:<name:\"DST-13\" description:\"NSM Endpoint\" type:AUTO_TAP enabled:true ip_addresses:\"10.60.1.6/30\" host_if_name:\"nsmJmECU3PvY\" namespace:<type:FILE_REF_NS filepath:\"/proc/15877/ns/net\" > tap:<temp_if_name:\"bh3ftivgk7g\" > > " | |
| 2019-01-22 11:30:19,899 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_add fd 26 private_data 9 idx 11 | |
| 2019-01-22 11:30:19,904 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:30:19.90406" level=info msg="Interface SRC-13 configured" loc="ifplugin/interface_config.go(320)" logger=vpp.if-conf | |
| 2019-01-22 11:30:19,927 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:30:19.92634" level=info msg="Interface DST-13 configured" loc="ifplugin/interface_config.go(320)" logger=vpp.if-conf | |
| 2019-01-22 11:30:19,956 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:30:19.95595" level=info msg="Linux interface DST-13 with hostIfName nsmJmECU3PvY configured" loc="ifplugin/interface_config.go(173)" logger=linux.if-conf | |
| 2019-01-22 11:30:19,957 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:30:19.95725" level=info msg="L2 XConnect pair DST-13-SRC-13 configured" loc="l2plugin/xconnect_config.go(126)" logger=vpp.xc-conf | |
| 2019-01-22 11:30:19,958 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:30:19.95830" level=info msg="L2 XConnect pair SRC-13-DST-13 configured" loc="l2plugin/xconnect_config.go(126)" logger=vpp.xc-conf | |
| 2019-01-22 11:30:19,961 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:30:19.96113" level=info msg="Route vrf0-8.8.8.8/30-10.60.1.6 registered" loc="l3plugin/route_config.go(173)" logger=vpp.l3-route-conf | |
| time="2019-01-22 11:30:19.96117" level=info msg="Route 8.8.8.8/30 -> 10.60.1.6 configured" loc="l3plugin/route_config.go(176)" logger=vpp.l3-route-conf | |
| time="2019-01-22 11:30:19.96121" level=info msg="there is no linux tap configuration entry for interface bh3ftivgk7g" loc="ifplugin/interface_config.go(351)" logger=linux.if-conf | |
| time="2019-01-22 11:30:19.96142" level=debug msg="TX Done - all events callbacks received" loc="syncbase/done.go(79)" logger=defaultLogger | |
| 2019-01-22 11:30:19,961 DEBG 'vppagent-dataplane' stdout output: | |
| 2019/01/22 11:30:19 Reporting span 62d3ec2338ede118:3e0761bfe0061b6:3e15c98251253270:1 | |
| 2019-01-22 11:30:19,962 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:30:19Z" level=info msg="Request(ConnectRequest) called with id:\"13\" payload:\"IP\" local_source:<id:\"13\" network_service:\"secure-intranet-connectivity\" mechanism:<type:MEM_INTERFACE parameters:<key:\"description\" value:\"Describe 12\" > parameters:<key:\"name\" value:\"12\" > parameters:<key:\"netnsInode\" value:\"4026532730\" > parameters:<key:\"socketfile\" value:\"12/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-2\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > labels:<key:\"app\" value:\"firewall\" > > local_destination:<id:\"14\" network_service:\"secure-intranet-connectivity\" mechanism:<type:KERNEL_INTERFACE parameters:<key:\"description\" value:\"NSM Endpoint\" > parameters:<key:\"name\" value:\"nsmJmECU3PvY\" > parameters:<key:\"netnsInode\" value:\"4026532813\" > parameters:<key:\"socketfile\" value:\"nsmJmECU3PvY/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-6\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > > returning: id:\"13\" payload:\"IP\" local_source:<id:\"13\" network_service:\"secure-intranet-connectivity\" mechanism:<type:MEM_INTERFACE parameters:<key:\"description\" value:\"Describe 12\" > parameters:<key:\"name\" value:\"12\" > parameters:<key:\"netnsInode\" value:\"4026532730\" > parameters:<key:\"socketfile\" value:\"12/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-2\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > labels:<key:\"app\" value:\"firewall\" > > local_destination:<id:\"14\" network_service:\"secure-intranet-connectivity\" mechanism:<type:KERNEL_INTERFACE parameters:<key:\"description\" value:\"NSM Endpoint\" > parameters:<key:\"name\" value:\"nsmJmECU3PvY\" > parameters:<key:\"netnsInode\" value:\"4026532813\" > parameters:<key:\"socketfile\" value:\"nsmJmECU3PvY/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-6\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > > " | |
| 2019/01/22 11:30:19 Reporting span 62d3ec2338ede118:3e15c98251253270:4e41a5878c1124b6:1 | |
| 2019-01-22 11:30:19,965 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:30:19.96546" level=info msg="transport: loopyWriter.run returning. connection error: desc = \"transport is closing\"" loc="grpclog/logger.go(55)" logger=grpc.grpc-server | |
| 2019-01-22 11:30:19,995 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:30:19Z" level=info msg="Request(ConnectRequest) called with id:\"11\" payload:\"IP\" remote_source:<id:\"11\" network_service:\"secure-intranet-connectivity\" mechanism:<type:VXLAN parameters:<key:\"dst_ip\" value:\"10.44.0.3\" > parameters:<key:\"src_ip\" value:\"10.32.0.5\" > parameters:<key:\"vni\" value:\"10\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > source_network_service_manager_name:\"kube-master\" destination_network_service_manager_name:\"kube-worker\" network_service_endpoint_name:\"secure-intranet-connectivitypqkck\" > local_destination:<id:\"12\" network_service:\"secure-intranet-connectivity\" mechanism:<type:MEM_INTERFACE parameters:<key:\"description\" value:\"NSM Endpoint\" > parameters:<key:\"name\" value:\"nsmBPkWFJGpM\" > parameters:<key:\"netnsInode\" value:\"4026532730\" > parameters:<key:\"socketfile\" value:\"nsmBPkWFJGpM/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-2\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > > " | |
| time="2019-01-22T11:30:19Z" level=info msg="m.GetParameters()[src_ip]: 10.44.0.3" | |
| time="2019-01-22T11:30:19Z" level=info msg="m.GetParameters()[dst_ip]: 10.32.0.5" | |
| time="2019-01-22T11:30:19Z" level=info msg="m.GetParameters()[vni]: 10" | |
| 2019-01-22 11:30:19,997 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:30:19Z" level=info msg="Sending DataChange to vppagent: Interfaces:<name:\"SRC-11\" type:VXLAN_TUNNEL enabled:true vxlan:<src_address:\"10.44.0.3\" dst_address:\"10.32.0.5\" vni:10 > > Interfaces:<name:\"DST-11\" type:MEMORY_INTERFACE enabled:true memif:<socket_filename:\"/var/lib/networkservicemesh/nsm-2/nsmBPkWFJGpM/memif.sock\" > > XCons:<receive_interface:\"SRC-11\" transmit_interface:\"DST-11\" > XCons:<receive_interface:\"DST-11\" transmit_interface:\"SRC-11\" > " | |
| 2019-01-22 11:30:20,002 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:30:20.00242" level=info msg="Interface SRC-11 configured" loc="ifplugin/interface_config.go(320)" logger=vpp.if-conf | |
| 2019-01-22 11:30:20,012 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:30:20.01179" level=info msg="Interface DST-11 configured" loc="ifplugin/interface_config.go(320)" logger=vpp.if-conf | |
| 2019-01-22 11:30:20,016 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:30:20.01596" level=info msg="L2 XConnect pair SRC-11-DST-11 configured" loc="l2plugin/xconnect_config.go(126)" logger=vpp.xc-conf | |
| 2019-01-22 11:30:20,017 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:30:20.01754" level=info msg="L2 XConnect pair DST-11-SRC-11 configured" loc="l2plugin/xconnect_config.go(126)" logger=vpp.xc-conf | |
| time="2019-01-22 11:30:20.01758" level=debug msg="TX Done - all events callbacks received" loc="syncbase/done.go(79)" logger=defaultLogger | |
| 2019-01-22 11:30:20,018 DEBG 'vppagent-dataplane' stdout output: | |
| 2019/01/22 11:30:20 Reporting span 67927ed9484ef8be:6afcfa729f7720c2:20c8602aedc0f37:1 | |
| 2019-01-22 11:30:20,018 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:30:20Z" level=info msg="Request(ConnectRequest) called with id:\"11\" payload:\"IP\" remote_source:<id:\"11\" network_service:\"secure-intranet-connectivity\" mechanism:<type:VXLAN parameters:<key:\"dst_ip\" value:\"10.44.0.3\" > parameters:<key:\"src_ip\" value:\"10.32.0.5\" > parameters:<key:\"vni\" value:\"10\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > source_network_service_manager_name:\"kube-master\" destination_network_service_manager_name:\"kube-worker\" network_service_endpoint_name:\"secure-intranet-connectivitypqkck\" > local_destination:<id:\"12\" network_service:\"secure-intranet-connectivity\" mechanism:<type:MEM_INTERFACE parameters:<key:\"description\" value:\"NSM Endpoint\" > parameters:<key:\"name\" value:\"nsmBPkWFJGpM\" > parameters:<key:\"netnsInode\" value:\"4026532730\" > parameters:<key:\"socketfile\" value:\"nsmBPkWFJGpM/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-2\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > > returning: id:\"11\" payload:\"IP\" remote_source:<id:\"11\" network_service:\"secure-intranet-connectivity\" mechanism:<type:VXLAN parameters:<key:\"dst_ip\" value:\"10.44.0.3\" > parameters:<key:\"src_ip\" value:\"10.32.0.5\" > parameters:<key:\"vni\" value:\"10\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > source_network_service_manager_name:\"kube-master\" destination_network_service_manager_name:\"kube-worker\" network_service_endpoint_name:\"secure-intranet-connectivitypqkck\" > local_destination:<id:\"12\" network_service:\"secure-intranet-connectivity\" mechanism:<type:MEM_INTERFACE parameters:<key:\"description\" value:\"NSM Endpoint\" > parameters:<key:\"name\" value:\"nsmBPkWFJGpM\" > parameters:<key:\"netnsInode\" value:\"4026532730\" > parameters:<key:\"socketfile\" value:\"nsmBPkWFJGpM/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-2\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > > " | |
| 2019/01/22 11:30:20 Reporting span 67927ed9484ef8be:20c8602aedc0f37:67927ed9484ef8be:1 | |
| 2019-01-22 11:30:20,018 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:30:20.01855" level=info msg="transport: loopyWriter.run returning. connection error: desc = \"transport is closing\"" loc="grpclog/logger.go(55)" logger=grpc.grpc-server | |
| 2019-01-22 11:30:22,196 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:30:22.19597" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:30:22,688 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_add fd 33 private_data 2 idx 15 | |
| 2019-01-22 11:30:22,711 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_add fd 36 private_data 131072 idx 14 | |
| 2019-01-22 11:30:22,732 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_add fd 37 private_data 9 idx 17 | |
| 2019-01-22 11:30:22,753 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_add fd 39 private_data 196608 idx 16 | |
| 2019-01-22 11:30:22,876 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: memif10/0: memif_msg_receive_disconnect: disconnect received | |
| 2019-01-22 11:30:22,876 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_del idx 15 | |
| 2019-01-22 11:30:22,876 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_del idx 14 | |
| 2019-01-22 11:30:22,881 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: memif9/0: memif_msg_receive_disconnect: disconnect received | |
| 2019-01-22 11:30:22,881 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_del idx 17 | |
| 2019-01-22 11:30:22,881 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_del idx 16 | |
| 2019-01-22 11:30:22,895 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:30:22Z" level=info msg="vppagent.DisconnectRequest called with &crossconnect.CrossConnect{Id:\"13\", Payload:\"IP\", Source:(*crossconnect.CrossConnect_LocalSource)(0xc000078160), Destination:(*crossconnect.CrossConnect_LocalDestination)(0xc000078178), XXX_NoUnkeyedLiteral:struct {}{}, XXX_unrecognized:[]uint8(nil), XXX_sizecache:0}" | |
| time="2019-01-22T11:30:22Z" level=info msg="Generated unique TempIfName: bh3ftjngk80 len(TempIfName) 11" | |
| time="2019-01-22T11:30:22Z" level=info msg="m.GetParameters()[name]: nsmJmECU3PvY" | |
| time="2019-01-22T11:30:22Z" level=info msg="Found /dev/vhost-net - using tapv2" | |
| time="2019-01-22T11:30:22Z" level=info msg="Sending DataChange to vppagent: Interfaces:<name:\"SRC-13\" type:MEMORY_INTERFACE enabled:true memif:<master:true socket_filename:\"/var/lib/networkservicemesh/nsm-2/12/memif.sock\" > > Interfaces:<name:\"DST-13\" type:TAP_INTERFACE enabled:true tap:<version:2 host_if_name:\"bh3ftjngk80\" > > XCons:<receive_interface:\"SRC-13\" transmit_interface:\"DST-13\" > XCons:<receive_interface:\"DST-13\" transmit_interface:\"SRC-13\" > StaticRoutes:<description:\"Route to 8.8.8.8/30\" dst_ip_addr:\"8.8.8.8/30\" next_hop_addr:\"10.60.1.6\" outgoing_interface:\"SRC-13\" > LinuxInterfaces:<name:\"DST-13\" description:\"NSM Endpoint\" type:AUTO_TAP enabled:true ip_addresses:\"10.60.1.6/30\" host_if_name:\"nsmJmECU3PvY\" namespace:<type:FILE_REF_NS filepath:\"/proc/15877/ns/net\" > tap:<temp_if_name:\"bh3ftjngk80\" > > " | |
| 2019-01-22 11:30:22,924 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:30:22.92469" level=info msg="Interface DST-13 removed" loc="ifplugin/interface_config.go(744)" logger=vpp.if-conf | |
| 2019-01-22 11:30:22,925 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:30:22.92483" level=info msg="Error status log for interface DST-13 cleared" loc="vpp/error_status.go(256)" logger=vpp | |
| 2019-01-22 11:30:22,927 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_del idx 11 | |
| 2019-01-22 11:30:22,928 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:30:22.92882" level=info msg="Interface SRC-13 removed" loc="ifplugin/interface_config.go(744)" logger=vpp.if-conf | |
| time="2019-01-22 11:30:22.92888" level=info msg="Error status log for interface SRC-13 cleared" loc="vpp/error_status.go(256)" logger=vpp | |
| 2019-01-22 11:30:22,929 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:30:22.92892" level=info msg="Linux tap DST-13 configuration unregistered and moved to cache" loc="ifplugin/interface_config.go(1112)" logger=linux.if-conf | |
| 2019-01-22 11:30:22,929 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:30:22.92932" level=error msg="failed to resolve unregistered VPP interface DST-13: failed to rename TAP interface from nsmJmECU3PvY to bh3ftivgk7g: Link not found\n/go/src/github.com/ligato/vpp-agent/plugins/linux/ifplugin/interface_config.go:1114 (0xc933de)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/watch_events.go:103 (0xdc829e)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/watch_events.go:61 (0xdc85ce)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/watch_events.go:34 (0xdc83b4)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/watch_events.go:60 (0xdc7b0f)\n/usr/local/go/src/runtime/asm_amd64.s:1333 (0x45c1b1)\n" loc="ifplugin/interface_config.go(1128)" logger=linux.if-conf | |
| 2019-01-22 11:30:22,929 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:30:22.92943" level=info msg="Route vrf0-8.8.8.8/30-10.60.1.6 unregistered" loc="l3plugin/route_config.go(410)" logger=vpp.l3-route-conf | |
| 2019-01-22 11:30:22,930 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:30:22.93036" level=info msg="Error status log: unknown type of prefix: vpp/config/v1/xconnect/" loc="vpp/error_status.go(262)" logger=vpp | |
| time="2019-01-22 11:30:22.93045" level=info msg="Error status log: unknown type of prefix: vpp/config/v1/xconnect/" loc="vpp/error_status.go(262)" logger=vpp | |
| time="2019-01-22 11:30:22.93050" level=info msg="Error status log: unknown type of prefix: vpp/config/v1/vrf/0/fib/8.8.8.8/30/" loc="vpp/error_status.go(262)" logger=vpp | |
| 2019-01-22 11:30:22,933 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:30:22.93302" level=error msg="failed to rename TAP interface from nsmJmECU3PvY to bh3ftivgk7g: Link not found\n/go/src/github.com/ligato/vpp-agent/plugins/linux/ifplugin/interface_config.go:688 (0xc8ec77)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/ifplugin/interface_config.go:713 (0xc8f4e0)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/ifplugin/interface_config.go:273 (0xc8a3b8)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/data_change.go:78 (0xdc37b2)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/data_change.go:41 (0xdc34ab)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/watch_events.go:78 (0xdc802f)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/watch_events.go:46 (0xdc84ac)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/watch_events.go:34 (0xdc83b4)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/watch_events.go:45 (0xdc7e33)\n/usr/local/go/src/runtime/asm_amd64.s:1333 (0x45c1b1)\n" loc="ifplugin/interface_config.go(1128)" logger=linux.if-conf | |
| time="2019-01-22 11:30:22.93312" level=debug msg="TX Done - all events callbacks received" loc="syncbase/done.go(79)" logger=defaultLogger | |
| 2019-01-22 11:30:22,934 DEBG 'vppagent-dataplane' stdout output: | |
| 2019/01/22 11:30:22 Reporting span 56f1acde3dc329f:4c2eb47a5dda0d97:374f2fde6ed1e234:1 | |
| time="2019-01-22T11:30:22Z" level=error msg="rpc error: code = Unknown desc = failed to rename TAP interface from nsmJmECU3PvY to bh3ftivgk7g: Link not found" | |
| time="2019-01-22T11:30:22Z" level=warning msg="rpc error: code = Unknown desc = failed to rename TAP interface from nsmJmECU3PvY to bh3ftivgk7g: Link not found" | |
| 2019/01/22 11:30:22 Reporting span 56f1acde3dc329f:374f2fde6ed1e234:56f1acde3dc329f:1 | |
| 2019-01-22 11:30:22,934 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:30:22.93454" level=info msg="transport: loopyWriter.run returning. connection error: desc = \"transport is closing\"" loc="grpclog/logger.go(55)" logger=grpc.grpc-server | |
| 2019-01-22 11:30:22,940 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:30:22Z" level=info msg="vppagent.DisconnectRequest called with &crossconnect.CrossConnect{Id:\"11\", Payload:\"IP\", Source:(*crossconnect.CrossConnect_RemoteSource)(0xc00000c1c0), Destination:(*crossconnect.CrossConnect_LocalDestination)(0xc00000c1d8), XXX_NoUnkeyedLiteral:struct {}{}, XXX_unrecognized:[]uint8(nil), XXX_sizecache:0}" | |
| 2019-01-22 11:30:22,941 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:30:22Z" level=info msg="m.GetParameters()[src_ip]: 10.44.0.3" | |
| time="2019-01-22T11:30:22Z" level=info msg="m.GetParameters()[dst_ip]: 10.32.0.5" | |
| time="2019-01-22T11:30:22Z" level=info msg="m.GetParameters()[vni]: 10" | |
| time="2019-01-22T11:30:22Z" level=info msg="Sending DataChange to vppagent: Interfaces:<name:\"SRC-11\" type:VXLAN_TUNNEL enabled:true vxlan:<src_address:\"10.44.0.3\" dst_address:\"10.32.0.5\" vni:10 > > Interfaces:<name:\"DST-11\" type:MEMORY_INTERFACE enabled:true memif:<socket_filename:\"/var/lib/networkservicemesh/nsm-2/nsmBPkWFJGpM/memif.sock\" > > XCons:<receive_interface:\"SRC-11\" transmit_interface:\"DST-11\" > XCons:<receive_interface:\"DST-11\" transmit_interface:\"SRC-11\" > " | |
| 2019-01-22 11:30:22,945 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:30:22.94544" level=info msg="Interface SRC-11 removed" loc="ifplugin/interface_config.go(744)" logger=vpp.if-conf | |
| 2019-01-22 11:30:22,946 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:30:22.94556" level=info msg="Error status log for interface SRC-11 cleared" loc="vpp/error_status.go(256)" logger=vpp | |
| 2019-01-22 11:30:22,949 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:30:22.94903" level=info msg="Interface DST-11 removed" loc="ifplugin/interface_config.go(744)" logger=vpp.if-conf | |
| 2019-01-22 11:30:22,949 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:30:22.94918" level=info msg="Error status log for interface DST-11 cleared" loc="vpp/error_status.go(256)" logger=vpp | |
| 2019-01-22 11:30:22,949 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:30:22.94936" level=info msg="Error status log: unknown type of prefix: vpp/config/v1/xconnect/" loc="vpp/error_status.go(262)" logger=vpp | |
| time="2019-01-22 11:30:22.94939" level=info msg="Error status log: unknown type of prefix: vpp/config/v1/xconnect/" loc="vpp/error_status.go(262)" logger=vpp | |
| time="2019-01-22 11:30:22.94941" level=debug msg="TX Done - all events callbacks received" loc="syncbase/done.go(79)" logger=defaultLogger | |
| 2019-01-22 11:30:22,950 DEBG 'vppagent-dataplane' stdout output: | |
| 2019/01/22 11:30:22 Reporting span 681f2ed27f1db968:3d0880653c11a102:6dab76faefa35b7a:1 | |
| 2019/01/22 11:30:22 Reporting span 681f2ed27f1db968:6dab76faefa35b7a:681f2ed27f1db968:1 | |
| 2019-01-22 11:30:22,950 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:30:22.95028" level=info msg="transport: loopyWriter.run returning. connection error: desc = \"transport is closing\"" loc="grpclog/logger.go(55)" logger=grpc.grpc-server | |
| 2019-01-22 11:30:32,196 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:30:32.19637" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:30:42,195 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:30:42.19509" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:30:52,194 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:30:52.19402" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:31:02,189 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:31:02.18927" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:31:12,189 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:31:12.18935" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:31:22,198 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:31:22.19841" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:31:32,191 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:31:32.19094" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:31:42,192 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:31:42.19268" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:31:52,174 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:31:52.17452" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:32:02,192 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:32:02.19203" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:32:12,193 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:32:12.19354" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:32:22,182 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:32:22.18184" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:32:32,201 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:32:32.20102" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:32:42,178 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:32:42.17865" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:32:52,196 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:32:52.19584" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:33:02,202 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:02.20201" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:33:12,202 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:12.20258" level=info msg="No subscription found for the notification message." msg_id=879 msg_size=1018 | |
| 2019-01-22 11:33:18,726 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:33:18Z" level=info msg="Request(ConnectRequest) called with id:\"17\" payload:\"IP\" local_source:<id:\"17\" network_service:\"secure-intranet-connectivity\" mechanism:<type:MEM_INTERFACE parameters:<key:\"description\" value:\"Describe 16\" > parameters:<key:\"name\" value:\"16\" > parameters:<key:\"netnsInode\" value:\"4026532730\" > parameters:<key:\"socketfile\" value:\"16/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-2\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > labels:<key:\"app\" value:\"firewall\" > > local_destination:<id:\"18\" network_service:\"secure-intranet-connectivity\" mechanism:<type:KERNEL_INTERFACE parameters:<key:\"description\" value:\"NSM Endpoint\" > parameters:<key:\"name\" value:\"nsmvjusU3b4c\" > parameters:<key:\"netnsInode\" value:\"4026532813\" > parameters:<key:\"socketfile\" value:\"nsmvjusU3b4c/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-6\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > > " | |
| time="2019-01-22T11:33:18Z" level=info msg="Generated unique TempIfName: bh3fuvngk8g len(TempIfName) 11" | |
| time="2019-01-22T11:33:18Z" level=info msg="m.GetParameters()[name]: nsmvjusU3b4c" | |
| time="2019-01-22T11:33:18Z" level=info msg="Found /dev/vhost-net - using tapv2" | |
| time="2019-01-22T11:33:18Z" level=info msg="Sending DataChange to vppagent: Interfaces:<name:\"SRC-17\" type:MEMORY_INTERFACE enabled:true memif:<master:true socket_filename:\"/var/lib/networkservicemesh/nsm-2/16/memif.sock\" > > Interfaces:<name:\"DST-17\" type:TAP_INTERFACE enabled:true tap:<version:2 host_if_name:\"bh3fuvngk8g\" > > XCons:<receive_interface:\"SRC-17\" transmit_interface:\"DST-17\" > XCons:<receive_interface:\"DST-17\" transmit_interface:\"SRC-17\" > StaticRoutes:<description:\"Route to 8.8.8.8/30\" dst_ip_addr:\"8.8.8.8/30\" next_hop_addr:\"10.60.1.6\" outgoing_interface:\"SRC-17\" > LinuxInterfaces:<name:\"DST-17\" description:\"NSM Endpoint\" type:AUTO_TAP enabled:true ip_addresses:\"10.60.1.6/30\" host_if_name:\"nsmvjusU3b4c\" namespace:<type:FILE_REF_NS filepath:\"/proc/15877/ns/net\" > tap:<temp_if_name:\"bh3fuvngk8g\" > > " | |
| 2019-01-22 11:33:18,729 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_add fd 26 private_data 11 idx 11 | |
| 2019-01-22 11:33:18,735 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:18.73571" level=info msg="Interface SRC-17 configured" loc="ifplugin/interface_config.go(320)" logger=vpp.if-conf | |
| 2019-01-22 11:33:18,768 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:18.76759" level=info msg="Interface DST-17 configured" loc="ifplugin/interface_config.go(320)" logger=vpp.if-conf | |
| 2019-01-22 11:33:18,805 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:18.80543" level=info msg="Linux interface DST-17 with hostIfName nsmvjusU3b4c configured" loc="ifplugin/interface_config.go(173)" logger=linux.if-conf | |
| 2019-01-22 11:33:18,807 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:18.80734" level=info msg="L2 XConnect pair SRC-17-DST-17 configured" loc="l2plugin/xconnect_config.go(126)" logger=vpp.xc-conf | |
| 2019-01-22 11:33:18,808 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:18.80853" level=info msg="L2 XConnect pair DST-17-SRC-17 configured" loc="l2plugin/xconnect_config.go(126)" logger=vpp.xc-conf | |
| 2019-01-22 11:33:18,809 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:18.80970" level=info msg="Route vrf0-8.8.8.8/30-10.60.1.6 registered" loc="l3plugin/route_config.go(173)" logger=vpp.l3-route-conf | |
| time="2019-01-22 11:33:18.80977" level=info msg="Route 8.8.8.8/30 -> 10.60.1.6 configured" loc="l3plugin/route_config.go(176)" logger=vpp.l3-route-conf | |
| 2019-01-22 11:33:18,810 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:18.81021" level=info msg="there is no linux tap configuration entry for interface bh3fuvngk8g" loc="ifplugin/interface_config.go(351)" logger=linux.if-conf | |
| time="2019-01-22 11:33:18.81025" level=debug msg="TX Done - all events callbacks received" loc="syncbase/done.go(79)" logger=defaultLogger | |
| 2019-01-22 11:33:18,811 DEBG 'vppagent-dataplane' stdout output: | |
| 2019/01/22 11:33:18 Reporting span 30952e58cb26294d:ab624889bb5d011:412a31ce3d7b2528:1 | |
| time="2019-01-22T11:33:18Z" level=info msg="Request(ConnectRequest) called with id:\"17\" payload:\"IP\" local_source:<id:\"17\" network_service:\"secure-intranet-connectivity\" mechanism:<type:MEM_INTERFACE parameters:<key:\"description\" value:\"Describe 16\" > parameters:<key:\"name\" value:\"16\" > parameters:<key:\"netnsInode\" value:\"4026532730\" > parameters:<key:\"socketfile\" value:\"16/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-2\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > labels:<key:\"app\" value:\"firewall\" > > local_destination:<id:\"18\" network_service:\"secure-intranet-connectivity\" mechanism:<type:KERNEL_INTERFACE parameters:<key:\"description\" value:\"NSM Endpoint\" > parameters:<key:\"name\" value:\"nsmvjusU3b4c\" > parameters:<key:\"netnsInode\" value:\"4026532813\" > parameters:<key:\"socketfile\" value:\"nsmvjusU3b4c/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-6\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > > returning: id:\"17\" payload:\"IP\" local_source:<id:\"17\" network_service:\"secure-intranet-connectivity\" mechanism:<type:MEM_INTERFACE parameters:<key:\"description\" value:\"Describe 16\" > parameters:<key:\"name\" value:\"16\" > parameters:<key:\"netnsInode\" value:\"4026532730\" > parameters:<key:\"socketfile\" value:\"16/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-2\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > labels:<key:\"app\" value:\"firewall\" > > local_destination:<id:\"18\" network_service:\"secure-intranet-connectivity\" mechanism:<type:KERNEL_INTERFACE parameters:<key:\"description\" value:\"NSM Endpoint\" > parameters:<key:\"name\" value:\"nsmvjusU3b4c\" > parameters:<key:\"netnsInode\" value:\"4026532813\" > parameters:<key:\"socketfile\" value:\"nsmvjusU3b4c/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-6\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > > " | |
| 2019/01/22 11:33:18 Reporting span 30952e58cb26294d:412a31ce3d7b2528:48edb7a1c525ac45:1 | |
| 2019-01-22 11:33:18,811 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:18.81113" level=info msg="transport: loopyWriter.run returning. connection error: desc = \"transport is closing\"" loc="grpclog/logger.go(55)" logger=grpc.grpc-server | |
| 2019-01-22 11:33:18,844 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:33:18Z" level=info msg="Request(ConnectRequest) called with id:\"15\" payload:\"IP\" remote_source:<id:\"15\" network_service:\"secure-intranet-connectivity\" mechanism:<type:VXLAN parameters:<key:\"dst_ip\" value:\"10.44.0.3\" > parameters:<key:\"src_ip\" value:\"10.32.0.5\" > parameters:<key:\"vni\" value:\"12\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > source_network_service_manager_name:\"kube-master\" destination_network_service_manager_name:\"kube-worker\" network_service_endpoint_name:\"secure-intranet-connectivitypqkck\" > local_destination:<id:\"16\" network_service:\"secure-intranet-connectivity\" mechanism:<type:MEM_INTERFACE parameters:<key:\"description\" value:\"NSM Endpoint\" > parameters:<key:\"name\" value:\"nsmrYK6FUIpz\" > parameters:<key:\"netnsInode\" value:\"4026532730\" > parameters:<key:\"socketfile\" value:\"nsmrYK6FUIpz/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-2\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > > " | |
| 2019-01-22 11:33:18,845 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:33:18Z" level=info msg="m.GetParameters()[src_ip]: 10.44.0.3" | |
| time="2019-01-22T11:33:18Z" level=info msg="m.GetParameters()[dst_ip]: 10.32.0.5" | |
| time="2019-01-22T11:33:18Z" level=info msg="m.GetParameters()[vni]: 12" | |
| time="2019-01-22T11:33:18Z" level=info msg="Sending DataChange to vppagent: Interfaces:<name:\"SRC-15\" type:VXLAN_TUNNEL enabled:true vxlan:<src_address:\"10.44.0.3\" dst_address:\"10.32.0.5\" vni:12 > > Interfaces:<name:\"DST-15\" type:MEMORY_INTERFACE enabled:true memif:<socket_filename:\"/var/lib/networkservicemesh/nsm-2/nsmrYK6FUIpz/memif.sock\" > > XCons:<receive_interface:\"SRC-15\" transmit_interface:\"DST-15\" > XCons:<receive_interface:\"DST-15\" transmit_interface:\"SRC-15\" > " | |
| 2019-01-22 11:33:18,853 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:18.85341" level=info msg="Interface SRC-15 configured" loc="ifplugin/interface_config.go(320)" logger=vpp.if-conf | |
| 2019-01-22 11:33:18,863 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:18.86340" level=info msg="Interface DST-15 configured" loc="ifplugin/interface_config.go(320)" logger=vpp.if-conf | |
| 2019-01-22 11:33:18,865 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:18.86558" level=info msg="L2 XConnect pair SRC-15-DST-15 configured" loc="l2plugin/xconnect_config.go(126)" logger=vpp.xc-conf | |
| 2019-01-22 11:33:18,869 DEBG 'vppagent-dataplane' stdout output: | |
| 2019/01/22 11:33:18 Reporting span 12d0868417c6509d:30dcc379ba6b3b19:32bd18ea0dba04a2:1 | |
| time="2019-01-22T11:33:18Z" level=info msg="Request(ConnectRequest) called with id:\"15\" payload:\"IP\" remote_source:<id:\"15\" network_service:\"secure-intranet-connectivity\" mechanism:<type:VXLAN parameters:<key:\"dst_ip\" value:\"10.44.0.3\" > parameters:<key:\"src_ip\" value:\"10.32.0.5\" > parameters:<key:\"vni\" value:\"12\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > source_network_service_manager_name:\"kube-master\" destination_network_service_manager_name:\"kube-worker\" network_service_endpoint_name:\"secure-intranet-connectivitypqkck\" > local_destination:<id:\"16\" network_service:\"secure-intranet-connectivity\" mechanism:<type:MEM_INTERFACE parameters:<key:\"description\" value:\"NSM Endpoint\" > parameters:<key:\"name\" value:\"nsmrYK6FUIpz\" > parameters:<key:\"netnsInode\" value:\"4026532730\" > parameters:<key:\"socketfile\" value:\"nsmrYK6FUIpz/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-2\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > > returning: id:\"15\" payload:\"IP\" remote_source:<id:\"15\" network_service:\"secure-intranet-connectivity\" mechanism:<type:VXLAN parameters:<key:\"dst_ip\" value:\"10.44.0.3\" > parameters:<key:\"src_ip\" value:\"10.32.0.5\" > parameters:<key:\"vni\" value:\"12\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > source_network_service_manager_name:\"kube-master\" destination_network_service_manager_name:\"kube-worker\" network_service_endpoint_name:\"secure-intranet-connectivitypqkck\" > local_destination:<id:\"16\" network_service:\"secure-intranet-connectivity\" mechanism:<type:MEM_INTERFACE parameters:<key:\"description\" value:\"NSM Endpoint\" > parameters:<key:\"name\" value:\"nsmrYK6FUIpz\" > parameters:<key:\"netnsInode\" value:\"4026532730\" > parameters:<key:\"socketfile\" value:\"nsmrYK6FUIpz/memif.sock\" > parameters:<key:\"workspace\" value:\"nsm-2\" > > context:<src_ip_addr:\"10.60.1.5/30\" dst_ip_addr:\"10.60.1.6/30\" src_ip_required:true dst_ip_required:true routes:<prefix:\"8.8.8.8/30\" > ip_neighbors:<ip:\"10.60.1.2\" hardware_address:\"da:60:7e:54:a2:b1\" > ip_neighbors:<ip:\"10.44.0.7\" hardware_address:\"6a:11:fe:70:3e:93\" > > > " | |
| 2019/01/22 11:33:18 Reporting span 12d0868417c6509d:32bd18ea0dba04a2:12d0868417c6509d:1 | |
| 2019-01-22 11:33:18,874 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:18.86909" level=info msg="L2 XConnect pair DST-15-SRC-15 configured" loc="l2plugin/xconnect_config.go(126)" logger=vpp.xc-conf | |
| time="2019-01-22 11:33:18.86914" level=debug msg="TX Done - all events callbacks received" loc="syncbase/done.go(79)" logger=defaultLogger | |
| time="2019-01-22 11:33:18.86987" level=info msg="transport: loopyWriter.run returning. connection error: desc = \"transport is closing\"" loc="grpclog/logger.go(55)" logger=grpc.grpc-server | |
| 2019-01-22 11:33:19,597 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_add fd 33 private_data 3 idx 16 | |
| 2019-01-22 11:33:19,625 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_add fd 36 private_data 196608 idx 17 | |
| 2019-01-22 11:33:19,639 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_add fd 37 private_data 11 idx 14 | |
| 2019-01-22 11:33:19,661 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: memif_plugin: clib_file_add fd 39 private_data 131072 idx 15 | |
| 2019-01-22 11:33:20,438 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: received signal SIGSEGV, PC 0x7f88612b124c, faulting address 0x7f8c61b8fa7c | |
| 2019-01-22 11:33:20,438 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: #0 0x00007f8860c7b97d 0x7f8860c7b97d | |
| 2019-01-22 11:33:20,439 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: #1 0x00007f88607d1890 0x7f88607d1890 | |
| 2019-01-22 11:33:20,439 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: #2 0x00007f88612b124c l2input_node_fn_avx2 + 0x5ac | |
| 2019-01-22 11:33:20,439 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: #3 0x00007f8860c4eb1f 0x7f8860c4eb1f | |
| 2019-01-22 11:33:20,440 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: #4 0x00007f8860c50c9d vlib_main + 0x6bd | |
| 2019-01-22 11:33:20,440 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: #5 0x00007f8860c7aa56 0x7f8860c7aa56 | |
| 2019-01-22 11:33:20,441 DEBG 'vpp' stdout output: | |
| /usr/bin/vpp[14456]: #6 0x00007f8860550fc4 0x7f8860550fc4 | |
| 2019-01-22 11:33:20,466 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:33:20Z" level=info msg="vppagent.DisconnectRequest called with &crossconnect.CrossConnect{Id:\"17\", Payload:\"IP\", Source:(*crossconnect.CrossConnect_LocalSource)(0xc000078130), Destination:(*crossconnect.CrossConnect_LocalDestination)(0xc000078150), XXX_NoUnkeyedLiteral:struct {}{}, XXX_unrecognized:[]uint8(nil), XXX_sizecache:0}" | |
| time="2019-01-22T11:33:20Z" level=info msg="Generated unique TempIfName: bh3fv07gk90 len(TempIfName) 11" | |
| time="2019-01-22T11:33:20Z" level=info msg="m.GetParameters()[name]: nsmvjusU3b4c" | |
| time="2019-01-22T11:33:20Z" level=info msg="Found /dev/vhost-net - using tapv2" | |
| time="2019-01-22T11:33:20Z" level=info msg="Sending DataChange to vppagent: Interfaces:<name:\"SRC-17\" type:MEMORY_INTERFACE enabled:true memif:<master:true socket_filename:\"/var/lib/networkservicemesh/nsm-2/16/memif.sock\" > > Interfaces:<name:\"DST-17\" type:TAP_INTERFACE enabled:true tap:<version:2 host_if_name:\"bh3fv07gk90\" > > XCons:<receive_interface:\"SRC-17\" transmit_interface:\"DST-17\" > XCons:<receive_interface:\"DST-17\" transmit_interface:\"SRC-17\" > StaticRoutes:<description:\"Route to 8.8.8.8/30\" dst_ip_addr:\"8.8.8.8/30\" next_hop_addr:\"10.60.1.6\" outgoing_interface:\"SRC-17\" > LinuxInterfaces:<name:\"DST-17\" description:\"NSM Endpoint\" type:AUTO_TAP enabled:true ip_addresses:\"10.60.1.6/30\" host_if_name:\"nsmvjusU3b4c\" namespace:<type:FILE_REF_NS filepath:\"/proc/15877/ns/net\" > tap:<temp_if_name:\"bh3fv07gk90\" > > " | |
| 2019-01-22 11:33:20,595 DEBG fd 9 closed, stopped monitoring <POutputDispatcher at 140206351829184 for <Subprocess at 140206351829832 with name vpp in state RUNNING> (stdout)> | |
| 2019-01-22 11:33:20,683 INFO exited: vpp (terminated by SIGABRT (core dumped); not expected) | |
| 2019-01-22 11:33:20,683 DEBG received SIGCLD indicating a child quit | |
| 2019-01-22 11:33:21,326 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:21.32666" level=warning msg="VPP health check probe timed out after 100ms (1. timeout)" | |
| 2019-01-22 11:33:21,327 DEBG event 0 sent to listener vpp_or_agent_not_running | |
| 2019-01-22 11:33:21,327 DEBG 'vpp_or_agent_not_running' stderr output: | |
| EVENT: ver:3.0 server:supervisor serial:0 pool:vpp_or_agent_not_running poolserial:0 eventname:PROCESS_STATE_EXITED len:69 | |
| DATA: processname:vpp groupname:vpp from_state:RUNNING expected:0 pid:14456 | |
| 2019-01-22 11:33:21,329 DEBG 'vpp_or_agent_not_running' stderr output: | |
| Killing supervisord with pid: 14436 | |
| 2019-01-22 11:33:21,329 DEBG 'vpp_or_agent_not_running' stdout output: | |
| RESULT 2 | |
| OK | |
| 2019-01-22 11:33:21,329 DEBG vpp_or_agent_not_running: event was processed | |
| 2019-01-22 11:33:21,329 DEBG vpp_or_agent_not_running: BUSY -> ACKNOWLEDGED | |
| 2019-01-22 11:33:21,329 WARN received SIGQUIT indicating exit request | |
| 2019-01-22 11:33:21,330 DEBG killing vppagent-dataplane (pid 14458) with signal SIGTERM | |
| 2019-01-22 11:33:21,330 INFO waiting for vpp_or_agent_not_running, vppagent-dataplane, agent to die | |
| 2019-01-22 11:33:21,331 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:33:21Z" level=info msg="Closing Dataplane Registration" | |
| time="2019-01-22T11:33:21Z" level=info msg="vppagent: connection to dataplane registrar socket /var/lib/networkservicemesh/nsm.dataplane-registrar.io.sock succeeded." | |
| 2019-01-22 11:33:21,333 DEBG fd 8 closed, stopped monitoring <POutputDispatcher at 140206351829904 for <Subprocess at 140206351830048 with name vpp_or_agent_not_running in state RUNNING> (stderr)> | |
| 2019-01-22 11:33:21,333 DEBG fd 6 closed, stopped monitoring <PEventListenerDispatcher at 140206351829040 for <Subprocess at 140206351830048 with name vpp_or_agent_not_running in state RUNNING> (stdout)> | |
| 2019-01-22 11:33:21,333 INFO exited: vpp_or_agent_not_running (exit status 0; expected) | |
| 2019-01-22 11:33:21,334 DEBG received SIGCLD indicating a child quit | |
| 2019-01-22 11:33:21,468 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:21.46773" level=error msg="failed to set interface SRC-17 down: no reply received within the timeout period 1s\n/go/src/github.com/ligato/vpp-agent/plugins/vpp/ifplugin/interface_config.go:753 (0xd4db40)\n/go/src/github.com/ligato/vpp-agent/plugins/vpp/ifplugin/interface_config.go:730 (0xd4c64c)\n/go/src/github.com/ligato/vpp-agent/plugins/vpp/data_change.go:420 (0xda4cbe)\n/go/src/github.com/ligato/vpp-agent/plugins/vpp/data_change.go:64 (0xda42a0)\n/go/src/github.com/ligato/vpp-agent/plugins/vpp/watch_events.go:139 (0xdc0d4f)\n/go/src/github.com/ligato/vpp-agent/plugins/vpp/watch_events.go:56 (0xdc20fc)\n/go/src/github.com/ligato/vpp-agent/plugins/vpp/watch_events.go:39 (0xdc1fab)\n/go/src/github.com/ligato/vpp-agent/plugins/vpp/watch_events.go:55 (0xdc0386)\n/usr/local/go/src/runtime/asm_amd64.s:1333 (0x45c1b1)\n" loc="ifplugin/interface_config.go(1010)" logger=vpp.if-conf | |
| time="2019-01-22 11:33:21.46782" level=info msg="Route vrf0-8.8.8.8/30-10.60.1.6 unregistered" loc="l3plugin/route_config.go(410)" logger=vpp.l3-route-conf | |
| time="2019-01-22 11:33:21.46790" level=info msg="Logging error for interface SRC-17" loc="vpp/error_status.go(89)" logger=vpp | |
| 2019-01-22 11:33:22,427 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:22.42729" level=warning msg="VPP health check probe timed out after 100ms (2. timeout)" | |
| time="2019-01-22 11:33:22.42732" level=error msg="VPP health check exceeded treshold for timeouts (>1), assuming disconnect" | |
| 2019-01-22 11:33:22,427 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:22.42766" level=info msg="Agent plugin state update." lastErr="VPP disconnected" loc="statuscheck/plugin_impl_statuscheck.go(182)" logger=status-check plugin=govpp state=error | |
| 2019-01-22 11:33:22,468 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:22.46857" level=error msg="failed to set interface DST-17 down: no reply received within the timeout period 1s\n/go/src/github.com/ligato/vpp-agent/plugins/vpp/ifplugin/interface_config.go:753 (0xd4db40)\n/go/src/github.com/ligato/vpp-agent/plugins/vpp/ifplugin/interface_config.go:730 (0xd4c64c)\n/go/src/github.com/ligato/vpp-agent/plugins/vpp/data_change.go:420 (0xda4cbe)\n/go/src/github.com/ligato/vpp-agent/plugins/vpp/data_change.go:64 (0xda42a0)\n/go/src/github.com/ligato/vpp-agent/plugins/vpp/watch_events.go:139 (0xdc0d4f)\n/go/src/github.com/ligato/vpp-agent/plugins/vpp/watch_events.go:56 (0xdc20fc)\n/go/src/github.com/ligato/vpp-agent/plugins/vpp/watch_events.go:39 (0xdc1fab)\n/go/src/github.com/ligato/vpp-agent/plugins/vpp/watch_events.go:55 (0xdc0386)\n/usr/local/go/src/runtime/asm_amd64.s:1333 (0x45c1b1)\n" loc="ifplugin/interface_config.go(1010)" logger=vpp.if-conf | |
| 2019-01-22 11:33:22,468 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:22.46875" level=info msg="Logging error for interface DST-17" loc="vpp/error_status.go(89)" logger=vpp | |
| 2019-01-22 11:33:22,469 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:22.46909" level=info msg="Linux tap DST-17 configuration unregistered and moved to cache" loc="ifplugin/interface_config.go(1112)" logger=linux.if-conf | |
| 2019-01-22 11:33:22,469 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:22.46947" level=error msg="failed to resolve unregistered VPP interface DST-17: failed to rename TAP interface from nsmvjusU3b4c to bh3fuvngk8g: Link not found\n/go/src/github.com/ligato/vpp-agent/plugins/linux/ifplugin/interface_config.go:1114 (0xc933de)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/watch_events.go:103 (0xdc829e)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/watch_events.go:61 (0xdc85ce)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/watch_events.go:34 (0xdc83b4)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/watch_events.go:60 (0xdc7b0f)\n/usr/local/go/src/runtime/asm_amd64.s:1333 (0x45c1b1)\n" loc="ifplugin/interface_config.go(1128)" logger=linux.if-conf | |
| 2019-01-22 11:33:22,469 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:22.46955" level=info msg="Error status log: unknown type of prefix: vpp/config/v1/xconnect/" loc="vpp/error_status.go(262)" logger=vpp | |
| time="2019-01-22 11:33:22.46957" level=info msg="Error status log: unknown type of prefix: vpp/config/v1/xconnect/" loc="vpp/error_status.go(262)" logger=vpp | |
| 2019-01-22 11:33:22,469 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:22.46959" level=info msg="Error status log: unknown type of prefix: vpp/config/v1/vrf/0/fib/8.8.8.8/30/" loc="vpp/error_status.go(262)" logger=vpp | |
| 2019-01-22 11:33:22,470 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:22.47023" level=error msg="failed to rename TAP interface from nsmvjusU3b4c to bh3fuvngk8g: Link not found\n/go/src/github.com/ligato/vpp-agent/plugins/linux/ifplugin/interface_config.go:688 (0xc8ec77)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/ifplugin/interface_config.go:713 (0xc8f4e0)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/ifplugin/interface_config.go:273 (0xc8a3b8)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/data_change.go:78 (0xdc37b2)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/data_change.go:41 (0xdc34ab)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/watch_events.go:78 (0xdc802f)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/watch_events.go:46 (0xdc84ac)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/watch_events.go:34 (0xdc83b4)\n/go/src/github.com/ligato/vpp-agent/plugins/linux/watch_events.go:45 (0xdc7e33)\n/usr/local/go/src/runtime/asm_amd64.s:1333 (0x45c1b1)\n" loc="ifplugin/interface_config.go(1128)" logger=linux.if-conf | |
| 2019-01-22 11:33:22,470 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:22.47033" level=debug msg="TX Done - all events callbacks received" loc="syncbase/done.go(79)" logger=defaultLogger | |
| 2019-01-22 11:33:22,471 DEBG 'vppagent-dataplane' stdout output: | |
| 2019/01/22 11:33:22 Reporting span 39089982f0abfeb1:4f390ec508bd080d:307cb8837ebd0ff0:1 | |
| time="2019-01-22T11:33:22Z" level=error msg="rpc error: code = Unknown desc = failed to rename TAP interface from nsmvjusU3b4c to bh3fuvngk8g: Link not found" | |
| time="2019-01-22T11:33:22Z" level=warning msg="rpc error: code = Unknown desc = failed to rename TAP interface from nsmvjusU3b4c to bh3fuvngk8g: Link not found" | |
| 2019/01/22 11:33:22 Reporting span 39089982f0abfeb1:307cb8837ebd0ff0:39089982f0abfeb1:1 | |
| 2019-01-22 11:33:22,471 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:22.47130" level=info msg="transport: loopyWriter.run returning. connection error: desc = \"transport is closing\"" loc="grpclog/logger.go(55)" logger=grpc.grpc-server | |
| 2019-01-22 11:33:22,475 DEBG 'vppagent-dataplane' stdout output: | |
| time="2019-01-22T11:33:22Z" level=info msg="vppagent.DisconnectRequest called with &crossconnect.CrossConnect{Id:\"15\", Payload:\"IP\", Source:(*crossconnect.CrossConnect_RemoteSource)(0xc00000c288), Destination:(*crossconnect.CrossConnect_LocalDestination)(0xc00000c2a0), XXX_NoUnkeyedLiteral:struct {}{}, XXX_unrecognized:[]uint8(nil), XXX_sizecache:0}" | |
| time="2019-01-22T11:33:22Z" level=info msg="m.GetParameters()[src_ip]: 10.44.0.3" | |
| time="2019-01-22T11:33:22Z" level=info msg="m.GetParameters()[dst_ip]: 10.32.0.5" | |
| time="2019-01-22T11:33:22Z" level=info msg="m.GetParameters()[vni]: 12" | |
| time="2019-01-22T11:33:22Z" level=info msg="Sending DataChange to vppagent: Interfaces:<name:\"SRC-15\" type:VXLAN_TUNNEL enabled:true vxlan:<src_address:\"10.44.0.3\" dst_address:\"10.32.0.5\" vni:12 > > Interfaces:<name:\"DST-15\" type:MEMORY_INTERFACE enabled:true memif:<socket_filename:\"/var/lib/networkservicemesh/nsm-2/nsmrYK6FUIpz/memif.sock\" > > XCons:<receive_interface:\"SRC-15\" transmit_interface:\"DST-15\" > XCons:<receive_interface:\"DST-15\" transmit_interface:\"SRC-15\" > " | |
| 2019-01-22 11:33:22,477 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:22.47708" level=error msg="processing request failed: not connected to VPP, ignoring the request" | |
| 2019-01-22 11:33:22,477 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:22.47719" level=error msg="failed to set interface SRC-15 down: not connected to VPP, ignoring the request\n/go/src/github.com/ligato/vpp-agent/plugins/vpp/ifplugin/interface_config.go:753 (0xd4db40)\n/go/src/github.com/ligato/vpp-agent/plugins/vpp/ifplugin/interface_config.go:730 (0xd4c64c)\n/go/src/github.com/ligato/vpp-agent/plugins/vpp/data_change.go:420 (0xda4cbe)\n/go/src/github.com/ligato/vpp-agent/plugins/vpp/data_change.go:64 (0xda42a0)\n/go/src/github.com/ligato/vpp-agent/plugins/vpp/watch_events.go:139 (0xdc0d4f)\n/go/src/github.com/ligato/vpp-agent/plugins/vpp/watch_events.go:56 (0xdc20fc)\n/go/src/github.com/ligato/vpp-agent/plugins/vpp/watch_events.go:39 (0xdc1fab)\n/go/src/github.com/ligato/vpp-agent/plugins/vpp/watch_events.go:55 (0xdc0386)\n/usr/local/go/src/runtime/asm_amd64.s:1333 (0x45c1b1)\n" loc="ifplugin/interface_config.go(1010)" logger=vpp.if-conf | |
| 2019-01-22 11:33:22,477 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:22.47742" level=info msg="Logging error for interface SRC-15" loc="vpp/error_status.go(89)" logger=vpp | |
| 2019-01-22 11:33:22,478 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:22.47826" level=error msg="processing request failed: not connected to VPP, ignoring the request" | |
| 2019-01-22 11:33:22,479 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:22.47897" level=error msg="failed to set interface DST-15 down: not connected to VPP, ignoring the request\n/go/src/github.com/ligato/vpp-agent/plugins/vpp/ifplugin/interface_config.go:753 (0xd4db40)\n/go/src/github.com/ligato/vpp-agent/plugins/vpp/ifplugin/interface_config.go:730 (0xd4c64c)\n/go/src/github.com/ligato/vpp-agent/plugins/vpp/data_change.go:420 (0xda4cbe)\n/go/src/github.com/ligato/vpp-agent/plugins/vpp/data_change.go:64 (0xda42a0)\n/go/src/github.com/ligato/vpp-agent/plugins/vpp/watch_events.go:139 (0xdc0d4f)\n/go/src/github.com/ligato/vpp-agent/plugins/vpp/watch_events.go:56 (0xdc20fc)\n/go/src/github.com/ligato/vpp-agent/plugins/vpp/watch_events.go:39 (0xdc1fab)\n/go/src/github.com/ligato/vpp-agent/plugins/vpp/watch_events.go:55 (0xdc0386)\n/usr/local/go/src/runtime/asm_amd64.s:1333 (0x45c1b1)\n" loc="ifplugin/interface_config.go(1010)" logger=vpp.if-conf | |
| 2019-01-22 11:33:22,481 DEBG 'vppagent-dataplane' stdout output: | |
| 2019/01/22 11:33:22 Reporting span 4eddbd426398259d:4eddbd426398259d:0:1 | |
| 2019-01-22 11:33:22,481 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:22.48039" level=info msg="Logging error for interface DST-15" loc="vpp/error_status.go(89)" logger=vpp | |
| time="2019-01-22 11:33:22.48047" level=info msg="Error status log: unknown type of prefix: vpp/config/v1/xconnect/" loc="vpp/error_status.go(262)" logger=vpp | |
| 2019-01-22 11:33:22,483 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:22.48327" level=debug msg="TX Done - all events callbacks received" loc="syncbase/done.go(79)" logger=defaultLogger | |
| 2019-01-22 11:33:22,483 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:22.48348" level=info msg="Error status log: unknown type of prefix: vpp/config/v1/xconnect/" loc="vpp/error_status.go(262)" logger=vpp | |
| 2019-01-22 11:33:22,484 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:22.48436" level=info msg="transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:9111->127.0.0.1:38714: read: connection reset by peer" loc="grpclog/logger.go(67)" logger=grpc.grpc-server | |
| 2019-01-22 11:33:22,484 DEBG fd 18 closed, stopped monitoring <POutputDispatcher at 140206351827456 for <Subprocess at 140206351828968 with name vppagent-dataplane in state STOPPING> (stdout)> | |
| 2019-01-22 11:33:22,484 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:22.48446" level=info msg="transport: loopyWriter.run returning. connection error: desc = \"transport is closing\"" loc="grpclog/logger.go(55)" logger=grpc.grpc-server | |
| 2019-01-22 11:33:22,485 INFO stopped: vppagent-dataplane (exit status 0) | |
| 2019-01-22 11:33:22,485 DEBG received SIGCLD indicating a child quit | |
| 2019-01-22 11:33:22,485 DEBG killing agent (pid 14457) with signal SIGTERM | |
| 2019-01-22 11:33:22,485 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:22.48531" level=info msg="Signal terminated received, stopping." loc="agent/agent.go(185)" logger=agent | |
| 2019-01-22 11:33:22,485 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:22.48567" level=info msg="Stopping agent" loc="agent/agent.go(246)" logger=agent | |
| 2019-01-22 11:33:22,488 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:22.48602" level=debug msg="GRPC server Serve: <nil>" loc="grpc/listen_and_serve.go(59)" logger=defaultLogger | |
| 2019-01-22 11:33:22,523 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:22.52348" level=info msg="Agent stopped" loc="agent/agent.go(268)" logger=agent | |
| 2019-01-22 11:33:22,528 DEBG 'agent' stdout output: | |
| time="2019-01-22 11:33:22.52800" level=debug msg="HTTP server Serve: http: Server closed" loc="rest/listen_and_serve.go(73)" logger=defaultLogger | |
| 2019-01-22 11:33:22,529 DEBG fd 15 closed, stopped monitoring <POutputDispatcher at 140206351827024 for <Subprocess at 140206351829472 with name agent in state STOPPING> (stdout)> | |
| 2019-01-22 11:33:22,529 INFO stopped: agent (exit status 0) | |
| 2019-01-22 11:33:22,529 DEBG received SIGCLD indicating a child quit |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment