search

ligato / vpp-agent

⚡️ Control plane management agent for FD.io's VPP
https://docs.ligato.io/
Apache License 2.0
252 stars 126 forks source link

vpp-agent taking 500ms (with WaitDone == true) for simple transaction #1748

Closed edwarnicke closed 4 years ago

edwarnicke commented 4 years ago

Placeholder

edwarnicke commented 4 years ago

Log output:

Oct 19 21:32:33.134 [INFO] SENDING UPDATE COMMIT: 
{
  "update": {
    "vpp_config": {
      "interfaces": [
        {
          "name": "server-3b292af6-7a09-4f83-a6f7-39f79fb84035",
          "type": "AF_PACKET",
          "enabled": true,
          "afpacket": {
            "hostIfName": "server-3b292af6"
          }
        },
        {
          "name": "client-3b292af6-7a09-4f83-a6f7-39f79fb84035",
          "type": "MEMIF",
          "enabled": true,
          "memif": {
            "socketFilename": "/proc/3601/fd/14"
          }
        }
      ],
      "xconnect_pairs": [
        {
          "receive_interface": "server-3b292af6-7a09-4f83-a6f7-39f79fb84035",
          "transmit_interface": "client-3b292af6-7a09-4f83-a6f7-39f79fb84035"
        },
        {
          "receive_interface": "client-3b292af6-7a09-4f83-a6f7-39f79fb84035",
          "transmit_interface": "server-3b292af6-7a09-4f83-a6f7-39f79fb84035"
        }
      ]
    },
    "linux_config": {
      "interfaces": [
        {
          "name": "server-3b292af6-7a09-4f83-a6f7-39f79fb84035-veth",
          "type": "VETH",
          "hostIfName": "server-3b292af6",
          "enabled": true,
          "veth": {
            "peerIfName": "server-3b292af6-7a09-4f83-a6f7-39f79fb84035",
            "rxChecksumOffloading": "CHKSM_OFFLOAD_DISABLED",
            "txChecksumOffloading": "CHKSM_OFFLOAD_DISABLED"
          }
        },
        {
          "name": "server-3b292af6-7a09-4f83-a6f7-39f79fb84035",
          "type": "VETH",
          "namespace": {
            "type": "FD",
            "reference": "/proc/3601/fd/12"
          },
          "hostIfName": "k2mns-3b292af6-",
          "enabled": true,
          "ipAddresses": [
            "10.0.0.1/32"
          ],
          "veth": {
            "peerIfName": "server-3b292af6-7a09-4f83-a6f7-39f79fb84035-veth",
            "rxChecksumOffloading": "CHKSM_OFFLOAD_DISABLED",
            "txChecksumOffloading": "CHKSM_OFFLOAD_DISABLED"
          }
        }
      ],
      "routes": [
        {
          "outgoing_interface": "server-3b292af6-7a09-4f83-a6f7-39f79fb84035",
          "scope": 3,
          "dst_network": "10.0.0.0/32"
        }
      ]
    },
    "netalloc_config": {}
  },
  "wait_done": true
}
time="2020-10-19 21:32:33.13562" level=debug msg="Push data with 7 KV pairs (source: grpc)" loc="orchestrator/dispatcher.go(110)" logger=dispatcher
time="2020-10-19 21:32:33.13569" level=debug msg=" - UPDATE: \"config/vpp/v2/interfaces/server-3b292af6-7a09-4f83-a6f7-39f79fb84035\" " loc="orchestrator/dispatcher.go(137)" logger=dispatcher
time="2020-10-19 21:32:33.13574" level=debug msg=" - UPDATE: \"config/vpp/v2/interfaces/client-3b292af6-7a09-4f83-a6f7-39f79fb84035\" " loc="orchestrator/dispatcher.go(137)" logger=dispatcher
time="2020-10-19 21:32:33.13579" level=debug msg=" - UPDATE: \"config/vpp/l2/v2/xconnect/server-3b292af6-7a09-4f83-a6f7-39f79fb84035\" " loc="orchestrator/dispatcher.go(137)" logger=dispatcher
time="2020-10-19 21:32:33.13582" level=debug msg=" - UPDATE: \"config/vpp/l2/v2/xconnect/client-3b292af6-7a09-4f83-a6f7-39f79fb84035\" " loc="orchestrator/dispatcher.go(137)" logger=dispatcher
time="2020-10-19 21:32:33.13585" level=debug msg=" - UPDATE: \"config/linux/interfaces/v2/interface/server-3b292af6-7a09-4f83-a6f7-39f79fb84035-veth\" " loc="orchestrator/dispatcher.go(137)" logger=dispatcher
time="2020-10-19 21:32:33.13590" level=debug msg=" - UPDATE: \"config/linux/interfaces/v2/interface/server-3b292af6-7a09-4f83-a6f7-39f79fb84035\" " loc="orchestrator/dispatcher.go(137)" logger=dispatcher
time="2020-10-19 21:32:33.13593" level=debug msg=" - UPDATE: \"config/linux/l3/v2/route/10.0.0.0/32/server-3b292af6-7a09-4f83-a6f7-39f79fb84035\" " loc="orchestrator/dispatcher.go(137)" logger=dispatcher
+======================================================================================================================+
| #11 - NBTransaction                                                                                                  |
+======================================================================================================================+
  * transaction arguments:
      - seqNum: 11
      - type: NB Transaction
      - values:
          - key: config/linux/interfaces/v2/interface/server-3b292af6-7a09-4f83-a6f7-39f79fb84035
            val: { name:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035"  type:VETH  namespace:{type:FD  reference:"/proc/3601/fd/12"}  host_if_name:"k2mns-3b292af6-"  enabled:true  ip_addresses:"10.0.0.1/32"  veth:{peer_if_name:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035-veth"  rx_checksum_offloading:CHKSM_OFFLOAD_DISABLED  tx_checksum_offloading:CHKSM_OFFLOAD_DISABLED} }
          - key: config/linux/interfaces/v2/interface/server-3b292af6-7a09-4f83-a6f7-39f79fb84035-veth
            val: { name:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035-veth"  type:VETH  host_if_name:"server-3b292af6"  enabled:true  veth:{peer_if_name:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035"  rx_checksum_offloading:CHKSM_OFFLOAD_DISABLED  tx_checksum_offloading:CHKSM_OFFLOAD_DISABLED} }
          - key: config/linux/l3/v2/route/10.0.0.0/32/server-3b292af6-7a09-4f83-a6f7-39f79fb84035
            val: { outgoing_interface:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035"  scope:LINK  dst_network:"10.0.0.0/32" }
          - key: config/vpp/l2/v2/xconnect/client-3b292af6-7a09-4f83-a6f7-39f79fb84035
            val: { receive_interface:"client-3b292af6-7a09-4f83-a6f7-39f79fb84035"  transmit_interface:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035" }
          - key: config/vpp/l2/v2/xconnect/server-3b292af6-7a09-4f83-a6f7-39f79fb84035
            val: { receive_interface:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035"  transmit_interface:"client-3b292af6-7a09-4f83-a6f7-39f79fb84035" }
          - key: config/vpp/v2/interfaces/client-3b292af6-7a09-4f83-a6f7-39f79fb84035
            val: { name:"client-3b292af6-7a09-4f83-a6f7-39f79fb84035"  type:MEMIF  enabled:true  memif:{socket_filename:"/proc/3601/fd/14"} }
          - key: config/vpp/v2/interfaces/server-3b292af6-7a09-4f83-a6f7-39f79fb84035
            val: { name:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035"  type:AF_PACKET  enabled:true  afpacket:{host_if_name:"server-3b292af6"} }

time="2020-10-19 21:32:33.19079" level=debug msg="Memif socket filename /proc/3601/fd/14 registered under ID 1" loc="descriptor/interface.go(949)" logger=vpp-ifplugin.if-descriptor
time="2020-10-19 21:32:33.19465" level=debug msg="publish add to ifplugin_ifstate{{client-3b292af6-7a09-4f83-a6f7-39f79fb84035 false false vpp-interface-index} 0xc000b5d4f0}" loc="mem/inmemory_name_mapping.go(277)" logger=vpp-ifplugin.if-descriptor
o----------------------------------------------------------------------------------------------------------------------o
  * executed operations (2020-10-19 21:32:33.136 +0000 UTC -> 2020-10-19 21:32:33.195 +0000 UTC, dur: 59ms):
      1. CREATE:
          - key: config/linux/interfaces/v2/interface/server-3b292af6-7a09-4f83-a6f7-39f79fb84035-veth
          - value: { name:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035-veth"  type:VETH  host_if_name:"server-3b292af6"  enabled:true  veth:{peer_if_name:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035"  rx_checksum_offloading:CHKSM_OFFLOAD_DISABLED  tx_checksum_offloading:CHKSM_OFFLOAD_DISABLED} } 
      2. CREATE:
          - key: config/linux/interfaces/v2/interface/server-3b292af6-7a09-4f83-a6f7-39f79fb84035
          - value: { name:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035"  type:VETH  namespace:{type:FD  reference:"/proc/3601/fd/12"}  host_if_name:"k2mns-3b292af6-"  enabled:true  ip_addresses:"10.0.0.1/32"  veth:{peer_if_name:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035-veth"  rx_checksum_offloading:CHKSM_OFFLOAD_DISABLED  tx_checksum_offloading:CHKSM_OFFLOAD_DISABLED} } 
      3. CREATE [DERIVED]:
          - key: linux/interface/server-3b292af6-7a09-4f83-a6f7-39f79fb84035/address/static/10.0.0.1/32
          - value: <EMPTY> 
      4. CREATE [PROPERTY]:
          - key: linux/interface/state/server-3b292af6-7a09-4f83-a6f7-39f79fb84035/UP
          - value: <EMPTY> 
      5. CREATE [PROPERTY]:
          - key: linux/interface/state/server-3b292af6-7a09-4f83-a6f7-39f79fb84035-veth/UP
          - value: <EMPTY> 
      6. CREATE:
          - key: config/linux/l3/v2/route/10.0.0.0/32/server-3b292af6-7a09-4f83-a6f7-39f79fb84035
          - value: { outgoing_interface:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035"  scope:LINK  dst_network:"10.0.0.0/32" } 
      7. CREATE [PROPERTY]:
          - key: linux/link-local-route/server-3b292af6-7a09-4f83-a6f7-39f79fb84035/dest-address/10.0.0.0/32
          - value: <EMPTY> 
      8. CREATE [NOOP IS-PENDING]:
          - key: config/vpp/l2/v2/xconnect/client-3b292af6-7a09-4f83-a6f7-39f79fb84035
          - value: { receive_interface:"client-3b292af6-7a09-4f83-a6f7-39f79fb84035"  transmit_interface:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035" } 
      9. CREATE [NOOP IS-PENDING]:
          - key: config/vpp/l2/v2/xconnect/server-3b292af6-7a09-4f83-a6f7-39f79fb84035
          - value: { receive_interface:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035"  transmit_interface:"client-3b292af6-7a09-4f83-a6f7-39f79fb84035" } 
      10. CREATE:
          - key: config/vpp/v2/interfaces/client-3b292af6-7a09-4f83-a6f7-39f79fb84035
          - value: { name:"client-3b292af6-7a09-4f83-a6f7-39f79fb84035"  type:MEMIF  enabled:true  memif:{socket_filename:"/proc/3601/fd/14"} } 
      11. CREATE [NOOP IS-PENDING]:
          - key: config/vpp/v2/interfaces/server-3b292af6-7a09-4f83-a6f7-39f79fb84035
          - value: { name:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035"  type:AF_PACKET  enabled:true  afpacket:{host_if_name:"server-3b292af6"} } 
x----------------------------------------------------------------------------------------------------------------------x
| #11 - NBTransaction                                                                                      took 58.8ms |
x----------------------------------------------------------------------------------------------------------------------x

+======================================================================================================================+
| #12 - SBNotification                                                                                                 |
+======================================================================================================================+
  * transaction arguments:
      - seqNum: 12
      - type: SB Notification
      - values:
          - key: vpp/interface/client-3b292af6-7a09-4f83-a6f7-39f79fb84035/link-state/DOWN
            val: <EMPTY>

time="2020-10-19 21:32:33.19527" level=info msg="Transaction #11 successful! (took 59.2ms)" loc="orchestrator/dispatcher.go(178)" logger=dispatcher
o----------------------------------------------------------------------------------------------------------------------o
  * executed operations (2020-10-19 21:32:33.195 +0000 UTC -> 2020-10-19 21:32:33.195 +0000 UTC, dur: 0s):
      1. CREATE [OBTAINED]:
          - key: vpp/interface/client-3b292af6-7a09-4f83-a6f7-39f79fb84035/link-state/DOWN
          - value: <EMPTY> 
x----------------------------------------------------------------------------------------------------------------------x
| #12 - SBNotification                                                                                      took 100µs |
x----------------------------------------------------------------------------------------------------------------------x

time="2020-10-19 21:32:33.19576" level=info msg="waiting for 3 pending keys to be done" loc="configurator/configurator.go(137)" logger=configurator.configurator
time="2020-10-19 21:32:33.19594" level=info msg="Transaction 12 successful!" loc="kvscheduler/txn_process.go(405)" logger=kvscheduler
+======================================================================================================================+
| #13 - SBNotification                                                                                                 |
+======================================================================================================================+
  * transaction arguments:
      - seqNum: 13
+======================================================================================================================+
| #6 - SBNotification                                                                                                  |
+======================================================================================================================+
  * transaction arguments:
      - seqNum: 6
      - type: SB Notification
      - values:
          - key: linux/interface/host-name/server-3b292af6
            val: <EMPTY>

o----------------------------------------------------------------------------------------------------------------------o
      - type: SB Notification
  * executed operations (2020-10-19 21:32:33.653 +0000 UTC -> 2020-10-19 21:32:33.653 +0000 UTC, dur: 0s):
      1. CREATE [OBTAINED]:
          - key: linux/interface/host-name/server-3b292af6
          - value: <EMPTY> 
x----------------------------------------------------------------------------------------------------------------------x
| #6 - SBNotification                                                                                       took 200µs |
x----------------------------------------------------------------------------------------------------------------------x

+======================================================================================================================+
| #4 - SBNotification                                                                                                  |
+======================================================================================================================+
  * transaction arguments:
      - seqNum: 4
      - type: SB Notification
      - values:
          - key: linux/interface/host-name/server-3b292af6
            val: <EMPTY>

time="2020-10-19 21:32:33.65325" level=info msg="Transaction 6 successful!" loc="kvscheduler/txn_process.go(405)" logger=kvscheduler
o----------------------------------------------------------------------------------------------------------------------o
  * executed operations (2020-10-19 21:32:33.653 +0000 UTC -> 2020-10-19 21:32:33.653 +0000 UTC, dur: 0s):
      1. CREATE [OBTAINED]:
          - key: linux/interface/host-name/server-3b292af6
          - value: <EMPTY> 
x----------------------------------------------------------------------------------------------------------------------x
| #4 - SBNotification                                                                                       took 200µs |
x----------------------------------------------------------------------------------------------------------------------x

time="2020-10-19 21:32:33.65334" level=info msg="Transaction 4 successful!" loc="kvscheduler/txn_process.go(405)" logger=kvscheduler
      - values:
          - key: linux/interface/host-name/server-3b292af6
            val: <EMPTY>

time="2020-10-19 21:32:33.67924" level=debug msg="publish add to ifplugin_ifstate{{server-3b292af6-7a09-4f83-a6f7-39f79fb84035 false false vpp-interface-index} 0xc000ac7ae0}" loc="mem/inmemory_name_mapping.go(277)" logger=vpp-ifplugin.if-descriptor
o----------------------------------------------------------------------------------------------------------------------o
  * executed operations (2020-10-19 21:32:33.653 +0000 UTC -> 2020-10-19 21:32:33.681 +0000 UTC, dur: 29ms):
      1. CREATE [OBTAINED]:
          - key: linux/interface/host-name/server-3b292af6
          - value: <EMPTY> 
      2. CREATE [WAS-PENDING]:
          - key: config/vpp/v2/interfaces/server-3b292af6-7a09-4f83-a6f7-39f79fb84035
          - value: { name:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035"  type:AF_PACKET  enabled:true  afpacket:{host_if_name:"server-3b292af6"} } 
      3. CREATE [WAS-PENDING]:
          - key: config/vpp/l2/v2/xconnect/client-3b292af6-7a09-4f83-a6f7-39f79fb84035
          - value: { receive_interface:"client-3b292af6-7a09-4f83-a6f7-39f79fb84035"  transmit_interface:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035" } 
      4. CREATE [WAS-PENDING]:
          - key: config/vpp/l2/v2/xconnect/server-3b292af6-7a09-4f83-a6f7-39f79fb84035
          - value: { receive_interface:"server-3b292af6-7a09-4f83-a6f7-39f79fb84035"  transmit_interface:"client-3b292af6-7a09-4f83-a6f7-39f79fb84035" } 
x----------------------------------------------------------------------------------------------------------------------x
| #13 - SBNotification                                                                                     took 28.9ms |
x----------------------------------------------------------------------------------------------------------------------x

time="2020-10-19 21:32:33.68161" level=info msg="Transaction 13 successful!" loc="kvscheduler/txn_process.go(405)" logger=kvscheduler
time="2020-10-19 21:32:33.68168" level=info msg="finished waiting for pending keys to be done (took 486.299447ms)" loc="configurator/configurator.go(147)" logger=configurator.configurator
time="2020-10-19 21:32:33.68175" level=debug msg="config update finished with 8 results" loc="configurator/configurator.go(153)" logger=configurator.configurator
+======================================================================================================================+
| #14 - SBNotification                                                                                                 |
+======================================================================================================================+
  * transaction arguments:
      - seqNum: 14
      - type: SB Notification
      - values:
          - key: vpp/interface/server-3b292af6-7a09-4f83-a6f7-39f79fb84035/link-state/DOWN
            val: <EMPTY>

o----------------------------------------------------------------------------------------------------------------------o
  * executed operations (2020-10-19 21:32:33.682 +0000 UTC -> 2020-10-19 21:32:33.682 +0000 UTC, dur: 0s):
      1. CREATE [OBTAINED]:
          - key: vpp/interface/server-3b292af6-7a09-4f83-a6f7-39f79fb84035/link-state/DOWN
          - value: <EMPTY> 
x----------------------------------------------------------------------------------------------------------------------x
| #14 - SBNotification                                                                                      took 100µs |
x----------------------------------------------------------------------------------------------------------------------x

Oct 19 21:32:33.681 [INFO] UPDATE COMMIT TOOK 547.210853ms
edwarnicke commented 4 years ago

Similar log output from a different event:

Oct 19 21:32:44.127 [INFO] SENDING UPDATE COMMIT: 
{
  "update": {
    "vpp_config": {
      "interfaces": [
        {
          "name": "server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0",
          "type": "MEMIF",
          "enabled": true,
          "memif": {
            "master": true,
            "socketFilename": "/tmp/forwarder-510286340/memif/362baafd-a5e4-4f6c-a6b2-e2bab84422f0.memif.socket"
          }
        },
        {
          "name": "client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0",
          "type": "AF_PACKET",
          "enabled": true,
          "afpacket": {
            "hostIfName": "client-362baafd"
          }
        }
      ],
      "xconnect_pairs": [
        {
          "receive_interface": "server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0",
          "transmit_interface": "client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"
        },
        {
          "receive_interface": "client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0",
          "transmit_interface": "server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"
        }
      ]
    },
    "linux_config": {
      "interfaces": [
        {
          "name": "client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0-veth",
          "type": "VETH",
          "hostIfName": "client-362baafd",
          "enabled": true,
          "veth": {
            "peerIfName": "client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0",
            "rxChecksumOffloading": "CHKSM_OFFLOAD_DISABLED",
            "txChecksumOffloading": "CHKSM_OFFLOAD_DISABLED"
          }
        },
        {
          "name": "client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0",
          "type": "VETH",
          "namespace": {
            "type": "FD",
            "reference": "/proc/3601/fd/16"
          },
          "hostIfName": "m2kns-362baafd-",
          "enabled": true,
          "ipAddresses": [
            "10.0.0.0/32"
          ],
          "veth": {
            "peerIfName": "client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0-veth",
            "rxChecksumOffloading": "CHKSM_OFFLOAD_DISABLED",
            "txChecksumOffloading": "CHKSM_OFFLOAD_DISABLED"
          }
        }
      ],
      "routes": [
        {
          "outgoing_interface": "client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0",
          "scope": 3,
          "dst_network": "10.0.0.1/32"
        }
      ]
    },
    "netalloc_config": {}
  },
  "wait_done": true
}
time="2020-10-19 21:32:44.12827" level=debug msg="Push data with 7 KV pairs (source: grpc)" loc="orchestrator/dispatcher.go(110)" logger=dispatcher
time="2020-10-19 21:32:44.12833" level=debug msg=" - UPDATE: \"config/vpp/v2/interfaces/server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0\" " loc="orchestrator/dispatcher.go(137)" logger=dispatcher
time="2020-10-19 21:32:44.12836" level=debug msg=" - UPDATE: \"config/vpp/v2/interfaces/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0\" " loc="orchestrator/dispatcher.go(137)" logger=dispatcher
time="2020-10-19 21:32:44.12840" level=debug msg=" - UPDATE: \"config/vpp/l2/v2/xconnect/server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0\" " loc="orchestrator/dispatcher.go(137)" logger=dispatcher
time="2020-10-19 21:32:44.12843" level=debug msg=" - UPDATE: \"config/vpp/l2/v2/xconnect/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0\" " loc="orchestrator/dispatcher.go(137)" logger=dispatcher
time="2020-10-19 21:32:44.12848" level=debug msg=" - UPDATE: \"config/linux/interfaces/v2/interface/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0-veth\" " loc="orchestrator/dispatcher.go(137)" logger=dispatcher
time="2020-10-19 21:32:44.12854" level=debug msg=" - UPDATE: \"config/linux/interfaces/v2/interface/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0\" " loc="orchestrator/dispatcher.go(137)" logger=dispatcher
time="2020-10-19 21:32:44.12857" level=debug msg=" - UPDATE: \"config/linux/l3/v2/route/10.0.0.1/32/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0\" " loc="orchestrator/dispatcher.go(137)" logger=dispatcher
+======================================================================================================================+
| #23 - NBTransaction                                                                                                  |
+======================================================================================================================+
  * transaction arguments:
      - seqNum: 23
      - type: NB Transaction
      - values:
          - key: config/linux/interfaces/v2/interface/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0
            val: { name:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"  type:VETH  namespace:{type:FD  reference:"/proc/3601/fd/16"}  host_if_name:"m2kns-362baafd-"  enabled:true  ip_addresses:"10.0.0.0/32"  veth:{peer_if_name:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0-veth"  rx_checksum_offloading:CHKSM_OFFLOAD_DISABLED  tx_checksum_offloading:CHKSM_OFFLOAD_DISABLED} }
          - key: config/linux/interfaces/v2/interface/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0-veth
            val: { name:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0-veth"  type:VETH  host_if_name:"client-362baafd"  enabled:true  veth:{peer_if_name:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"  rx_checksum_offloading:CHKSM_OFFLOAD_DISABLED  tx_checksum_offloading:CHKSM_OFFLOAD_DISABLED} }
          - key: config/linux/l3/v2/route/10.0.0.1/32/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0
            val: { outgoing_interface:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"  scope:LINK  dst_network:"10.0.0.1/32" }
          - key: config/vpp/l2/v2/xconnect/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0
            val: { receive_interface:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"  transmit_interface:"server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0" }
          - key: config/vpp/l2/v2/xconnect/server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0
            val: { receive_interface:"server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"  transmit_interface:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0" }
          - key: config/vpp/v2/interfaces/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0
            val: { name:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"  type:AF_PACKET  enabled:true  afpacket:{host_if_name:"client-362baafd"} }
          - key: config/vpp/v2/interfaces/server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0
            val: { name:"server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"  type:MEMIF  enabled:true  memif:{master:true  socket_filename:"/tmp/forwarder-510286340/memif/362baafd-a5e4-4f6c-a6b2-e2bab84422f0.memif.socket"} }

time="2020-10-19 21:32:44.17598" level=debug msg="Memif socket filename /tmp/forwarder-510286340/memif/362baafd-a5e4-4f6c-a6b2-e2bab84422f0.memif.socket registered under ID 2" loc="descriptor/interface.go(949)" logger=vpp-ifplugin.if-descriptor
vpp[3609]: memif_plugin: clib_file_add fd 15 private_data 2 idx 7

Oct 19 21:32:29.226 [INFO] [cmd:vpp] vpp[3609]: memif_plugin: clib_file_add fd 15 private_data 2 idx 7
time="2020-10-19 21:32:44.17974" level=debug msg="publish add to ifplugin_ifstate{{server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0 false false vpp-interface-index} 0xc000665590}" loc="mem/inmemory_name_mapping.go(277)" logger=vpp-ifplugin.if-descriptor
o----------------------------------------------------------------------------------------------------------------------o
  * executed operations (2020-10-19 21:32:44.129 +0000 UTC -> 2020-10-19 21:32:44.18 +0000 UTC, dur: 51ms):
      1. CREATE:
          - key: config/linux/interfaces/v2/interface/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0-veth
          - value: { name:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0-veth"  type:VETH  host_if_name:"client-362baafd"  enabled:true  veth:{peer_if_name:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"  rx_checksum_offloading:CHKSM_OFFLOAD_DISABLED  tx_checksum_offloading:CHKSM_OFFLOAD_DISABLED} } 
      2. CREATE:
          - key: config/linux/interfaces/v2/interface/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0
          - value: { name:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"  type:VETH  namespace:{type:FD  reference:"/proc/3601/fd/16"}  host_if_name:"m2kns-362baafd-"  enabled:true  ip_addresses:"10.0.0.0/32"  veth:{peer_if_name:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0-veth"  rx_checksum_offloading:CHKSM_OFFLOAD_DISABLED  tx_checksum_offloading:CHKSM_OFFLOAD_DISABLED} } 
      3. CREATE [DERIVED]:
          - key: linux/interface/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0/address/static/10.0.0.0/32
          - value: <EMPTY> 
      4. CREATE [PROPERTY]:
          - key: linux/interface/state/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0/UP
          - value: <EMPTY> 
      5. CREATE [PROPERTY]:
          - key: linux/interface/state/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0-veth/UP
          - value: <EMPTY> 
      6. CREATE:
          - key: config/linux/l3/v2/route/10.0.0.1/32/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0
          - value: { outgoing_interface:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"  scope:LINK  dst_network:"10.0.0.1/32" } 
      7. CREATE [PROPERTY]:
          - key: linux/link-local-route/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0/dest-address/10.0.0.1/32
          - value: <EMPTY> 
      8. CREATE [NOOP IS-PENDING]:
          - key: config/vpp/l2/v2/xconnect/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0
          - value: { receive_interface:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"  transmit_interface:"server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0" } 
      9. CREATE [NOOP IS-PENDING]:
          - key: config/vpp/l2/v2/xconnect/server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0
          - value: { receive_interface:"server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"  transmit_interface:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0" } 
      10. CREATE [NOOP IS-PENDING]:
          - key: config/vpp/v2/interfaces/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0
          - value: { name:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"  type:AF_PACKET  enabled:true  afpacket:{host_if_name:"client-362baafd"} } 
      11. CREATE:
          - key: config/vpp/v2/interfaces/server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0
          - value: { name:"server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"  type:MEMIF  enabled:true  memif:{master:true  socket_filename:"/tmp/forwarder-510286340/memif/362baafd-a5e4-4f6c-a6b2-e2bab84422f0.memif.socket"} } 
x----------------------------------------------------------------------------------------------------------------------x
| #23 - NBTransaction                                                                                      took 51.3ms |
x----------------------------------------------------------------------------------------------------------------------x

+======================================================================================================================+
| #24 - SBNotification                                                                                                 |
+======================================================================================================================+
  * transaction arguments:
      - seqNum: 24
      - type: SB Notification
      - values:
          - key: vpp/interface/server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0/link-state/DOWN
            val: <EMPTY>

time="2020-10-19 21:32:44.18041" level=info msg="Transaction #23 successful! (took 51.7ms)" loc="orchestrator/dispatcher.go(178)" logger=dispatcher
o----------------------------------------------------------------------------------------------------------------------o
  * executed operations (2020-10-19 21:32:44.18 +0000 UTC -> 2020-10-19 21:32:44.18 +0000 UTC, dur: 0s):
      1. CREATE [OBTAINED]:
          - key: vpp/interface/server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0/link-state/DOWN
          - value: <EMPTY> 
x----------------------------------------------------------------------------------------------------------------------x
| #24 - SBNotification                                                                                      took 100µs |
x----------------------------------------------------------------------------------------------------------------------x

time="2020-10-19 21:32:44.18053" level=info msg="Transaction 24 successful!" loc="kvscheduler/txn_process.go(405)" logger=kvscheduler
time="2020-10-19 21:32:44.18060" level=info msg="waiting for 3 pending keys to be done" loc="configurator/configurator.go(137)" logger=configurator.configurator
+======================================================================================================================+
| #6 - SBNotification                                                                                                  |
+======================================================================================================================+
  * transaction arguments:
      - seqNum: 6
      - type: SB Notification
      - values:
          - key: linux/interface/host-name/client-362baafd
            val: <EMPTY>

o----------------------------------------------------------------------------------------------------------------------o
  * executed operations (2020-10-19 21:32:44.646 +0000 UTC -> 2020-10-19 21:32:44.646 +0000 UTC, dur: 0s):
      1. CREATE [OBTAINED]:
          - key: linux/interface/host-name/client-362baafd
          - value: <EMPTY> 
x----------------------------------------------------------------------------------------------------------------------x
+======================================================================================================================+
| #11 - SBNotification                                                                                                 |
+======================================================================================================================+
  * transaction arguments:
      - seqNum: 11
      - type: SB Notification
      - values:
          - key: linux/interface/host-name/client-362baafd
+======================================================================================================================+
| #25 - SBNotification                                                                                                 |
            val: <EMPTY>
+======================================================================================================================+
  * transaction arguments:

      - seqNum: 25
o----------------------------------------------------------------------------------------------------------------------o
      - type: SB Notification
  * executed operations (2020-10-19 21:32:44.646 +0000 UTC -> 2020-10-19 21:32:44.646 +0000 UTC, dur: 0s):
      - values:
      1. CREATE [OBTAINED]:
          - key: linux/interface/host-name/client-362baafd
            val: <EMPTY>
          - key: linux/interface/host-name/client-362baafd

          - value: <EMPTY> 
x----------------------------------------------------------------------------------------------------------------------x
| #11 - SBNotification                                                                                      took 100µs |
x----------------------------------------------------------------------------------------------------------------------x

time="2020-10-19 21:32:44.64633" level=info msg="Transaction 11 successful!" loc="kvscheduler/txn_process.go(405)" logger=kvscheduler
| #6 - SBNotification                                                                                       took 100µs |
x----------------------------------------------------------------------------------------------------------------------x

time="2020-10-19 21:32:44.64634" level=info msg="Transaction 6 successful!" loc="kvscheduler/txn_process.go(405)" logger=kvscheduler
time="2020-10-19 21:32:44.67663" level=debug msg="publish add to ifplugin_ifstate{{client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0 false false vpp-interface-index} 0xc000ac6050}" loc="mem/inmemory_name_mapping.go(277)" logger=vpp-ifplugin.if-descriptor
time="2020-10-19 21:32:44.67928" level=info msg="finished waiting for pending keys to be done (took 498.663608ms)" loc="configurator/configurator.go(147)" logger=configurator.configurator
time="2020-10-19 21:32:44.67935" level=debug msg="config update finished with 8 results" loc="configurator/configurator.go(153)" logger=configurator.configurator
Oct 19 21:32:44.679 [INFO] UPDATE COMMIT TOOK 552.087497ms
o----------------------------------------------------------------------------------------------------------------------o
  * executed operations (2020-10-19 21:32:44.646 +0000 UTC -> 2020-10-19 21:32:44.679 +0000 UTC, dur: 33ms):
      1. CREATE [OBTAINED]:
          - key: linux/interface/host-name/client-362baafd
          - value: <EMPTY> 
      2. CREATE [WAS-PENDING]:
          - key: config/vpp/v2/interfaces/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0
          - value: { name:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"  type:AF_PACKET  enabled:true  afpacket:{host_if_name:"client-362baafd"} } 
      3. CREATE [WAS-PENDING]:
          - key: config/vpp/l2/v2/xconnect/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0
          - value: { receive_interface:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"  transmit_interface:"server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0" } 
      4. CREATE [WAS-PENDING]:
          - key: config/vpp/l2/v2/xconnect/server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0
          - value: { receive_interface:"server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0"  transmit_interface:"client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0" } 
Oct 19 21:32:44.679 [INFO] [cmd:forwarder] >><<---------------------------------------- response={"id":"362baafd-a5e4-4f6c-a6b2-e2bab84422f0","network_service":"m2kns","mechanism":{"cls":"LOCAL","type":"MEMIF","parameters":{"inodeURL":"inode://109/1463156"}},"context":{"ip_context":{"src_ip_addr":"10.0.0.1/32","dst_ip_addr":"10.0.0.0/32"}},"path":{"index":1,"path_segments":[{"name":"testClient","id":"91b29fdb-b41a-4d8d-bc2e-b9517f1aba6c","token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJleHAiOjE2MDMxNDY3NDksInN1YiI6InNwaWZmZTovL2V4YW1wbGUub3JnL2NtZC1mb3J3YXJkZXItdnBwYWdlbnQudGVzdCJ9.7utLndTifFJ4f5isKk55C4vRA1B4uW7cfCRV0E2438unyDtquCucIVPFJAGUhpL-3yPBISC81qa22_x1wSSZ_g","expires":{"seconds":1603146749}},{"name":"forwarder","id":"362baafd-a5e4-4f6c-a6b2-e2bab84422f0","token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJhdWQiOiJzcGlmZmU6Ly9leGFtcGxlLm9yZy9jbWQtZm9yd2FyZGVyLXZwcGFnZW50LnRlc3QiLCJleHAiOjE2MDMxNDY3NDksInN1YiI6InNwaWZmZTovL2V4YW1wbGUub3JnL2ZvcndhcmRlciJ9.187rsKzzA_pPCFGD11CEMKkUtzh2uC2ruF1BQWZcnZ6WYGuoIZlroSByDJ61XxAEptZeM9WtQ1C12DRaHKWkPg","expires":{"seconds":1603146749}},{"name":"testServer","id":"2de8cbc8-c391-420e-b771-bf1c8121ab0d","token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJhdWQiOiJzcGlmZmU6Ly9leGFtcGxlLm9yZy9mb3J3YXJkZXIiLCJleHAiOjE2MDMxNDY3NDksInN1YiI6InNwaWZmZTovL2V4YW1wbGUub3JnL2NtZC1mb3J3YXJkZXItdnBwYWdlbnQudGVzdCJ9.Mdc3VufZs5dMSZfzQ-CJNWPq7Bklv7FR-9P-biLDCkKUvVAwipEyaY6A5tUa6G28NKiNEa038vtJNUzo6ZW3qQ","expires":{"seconds":1603146749}}]}} span={}
Oct 19 21:32:44.680 [INFO] [cmd:forwarder] >><<-------------------------------------- response={"id":"362baafd-a5e4-4f6c-a6b2-e2bab84422f0","network_service":"m2kns","mechanism":{"cls":"LOCAL","type":"MEMIF","parameters":{"inodeURL":"inode://109/1463156"}},"context":{"ip_context":{"src_ip_addr":"10.0.0.1/32","dst_ip_addr":"10.0.0.0/32"}},"path":{"index":1,"path_segments":[{"name":"testClient","id":"91b29fdb-b41a-4d8d-bc2e-b9517f1aba6c","token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJleHAiOjE2MDMxNDY3NDksInN1YiI6InNwaWZmZTovL2V4YW1wbGUub3JnL2NtZC1mb3J3YXJkZXItdnBwYWdlbnQudGVzdCJ9.7utLndTifFJ4f5isKk55C4vRA1B4uW7cfCRV0E2438unyDtquCucIVPFJAGUhpL-3yPBISC81qa22_x1wSSZ_g","expires":{"seconds":1603146749}},{"name":"forwarder","id":"362baafd-a5e4-4f6c-a6b2-e2bab84422f0","token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJhdWQiOiJzcGlmZmU6Ly9leGFtcGxlLm9yZy9jbWQtZm9yd2FyZGVyLXZwcGFnZW50LnRlc3QiLCJleHAiOjE2MDMxNDY3NDksInN1YiI6InNwaWZmZTovL2V4YW1wbGUub3JnL2ZvcndhcmRlciJ9.187rsKzzA_pPCFGD11CEMKkUtzh2uC2ruF1BQWZcnZ6WYGuoIZlroSByDJ61XxAEptZeM9WtQ1C12DRaHKWkPg","expires":{"seconds":1603146749}},{"name":"testServer","id":"2de8cbc8-c391-420e-b771-bf1c8121ab0d","token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJhdWQiOiJzcGlmZmU6Ly9leGFtcGxlLm9yZy9mb3J3YXJkZXIiLCJleHAiOjE2MDMxNDY3NDksInN1YiI6InNwaWZmZTovL2V4YW1wbGUub3JnL2NtZC1mb3J3YXJkZXItdnBwYWdlbnQudGVzdCJ9.Mdc3VufZs5dMSZfzQ-CJNWPq7Bklv7FR-9P-biLDCkKUvVAwipEyaY6A5tUa6G28NKiNEa038vtJNUzo6ZW3qQ","expires":{"seconds":1603146749}}]}} span={}
Oct 19 21:32:44.680 [DEBU] [operation:github.com/networkservicemesh/sdk-vppagent/pkg/networkservice/metrics/metricsServer.Request] [span:{}] MetricsServer: Request Metrics
x----------------------------------------------------------------------------------------------------------------------x
| #25 - SBNotification                                                                                     took 32.6ms |
x----------------------------------------------------------------------------------------------------------------------x

time="2020-10-19 21:32:44.67971" level=info msg="Transaction 25 successful!" loc="kvscheduler/txn_process.go(405)" logger=kvscheduler
+======================================================================================================================+
| #26 - SBNotification                                                                                                 |
+======================================================================================================================+
  * transaction arguments:
      - seqNum: 26
      - type: SB Notification
      - values:
          - key: vpp/interface/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0/link-state/DOWN
            val: <EMPTY>

o----------------------------------------------------------------------------------------------------------------------o
  * executed operations (2020-10-19 21:32:44.68 +0000 UTC -> 2020-10-19 21:32:44.68 +0000 UTC, dur: 0s):
      1. CREATE [OBTAINED]:
          - key: vpp/interface/client-362baafd-a5e4-4f6c-a6b2-e2bab84422f0/link-state/DOWN
          - value: <EMPTY> 
x----------------------------------------------------------------------------------------------------------------------x
| #26 - SBNotification                                                                                      took 100µs |
x----------------------------------------------------------------------------------------------------------------------x

time="2020-10-19 21:32:44.67994" level=info msg="Transaction 26 successful!" loc="kvscheduler/txn_process.go(405)" logger=kvscheduler
time="2020-10-19 21:32:44.68123" level=debug msg="streaming 4 interface stats" loc="telemetry/stats_poller.go(106)" logger=telemetry.stats-poller
time="2020-10-19 21:32:44.68137" level=debug msg="sending vpp stats: interface:{name:\"UNTAGGED-local0\"  rx:{}  tx:{}  rx_unicast:{}  rx_multicast:{}  rx_broadcast:{}  tx_unicast:{}  tx_multicast:{}  tx_broadcast:{}}" loc="telemetry/stats_poller.go(48)" logger=telemetry.stats-poller
time="2020-10-19 21:32:44.68152" level=debug msg="sending vpp stats: interface:{name:\"eth0\"  rx:{packets:2  bytes:112}  tx:{packets:1  bytes:42}  rx_unicast:{}  rx_multicast:{}  rx_broadcast:{}  tx_unicast:{}  tx_multicast:{}  tx_broadcast:{}  drops:2  ip6:1}" loc="telemetry/stats_poller.go(48)" logger=telemetry.stats-poller
time="2020-10-19 21:32:44.68167" level=debug msg="sending vpp stats: interface:{name:\"server-362baafd-a5e4-4f6c-a6b2-e2bab84422f0\"  rx:{}  tx:{}  rx_unicast:{}  rx_multicast:{}  rx_broadcast:{}  tx_unicast:{}  tx_multicast:{}  tx_broadcast:{}}" loc="telemetry/stats_poller.go(48)" logger=telemetry.stats-poller
edwarnicke commented 4 years ago

Looks like 2ms from when I send my call till you start your first execution: super good!

Oct 19 21:32:44.127�[36m [INFO] �[0mSENDING UPDATE COMMIT: 
...
executed operations (2020-10-19 21:32:44.129 +0000 UTC -> 2020-10-19 21:32:44.18 +0000 UTC, dur: 51ms):

and pretty much instantly returned after its last execution (note: log ordering got a little messed up here, but check the timestamps).

Oct 19 21:32:44.679�[36m [INFO] �[0mUPDATE COMMIT TOOK 552.087497ms
* executed operations (2020-10-19 21:32:44.68 +0000 UTC -> 2020-10-19 21:32:44.68 +0000 UTC, dur: 0s):
edwarnicke commented 4 years ago

Looks like 551ms is accounted for by the execution - so we know where all the time is going here.

executed operations (2020-10-19 21:32:44.129 +0000 UTC -> 2020-10-19 21:32:44.18 +0000 UTC, dur: 51ms):
...
* executed operations (2020-10-19 21:32:44.18 +0000 UTC -> 2020-10-19 21:32:44.18 +0000 UTC, dur: 0s):
...
* executed operations (2020-10-19 21:32:44.646 +0000 UTC -> 2020-10-19 21:32:44.646 +0000 UTC, dur: 0s):
...
* executed operations (2020-10-19 21:32:44.646 +0000 UTC -> 2020-10-19 21:32:44.646 +0000 UTC, dur: 0s):
...
* executed operations (2020-10-19 21:32:44.646 +0000 UTC -> 2020-10-19 21:32:44.679 +0000 UTC, dur: 33ms):
...
 * executed operations (2020-10-19 21:32:44.68 +0000 UTC -> 2020-10-19 21:32:44.68 +0000 UTC, dur: 0s):
edwarnicke commented 4 years ago

Related to: https://github.com/ligato/vpp-agent/issues/1739

ondrej-fabry commented 4 years ago

Could you mention exact vpp-agent version as well? If you print the header of the log it is next to the logo.

edwarnicke commented 4 years ago

vppagent version from the go.mod: 

go.ligato.io/vpp-agent/v3 v3.2.0-alpha.0.20201016122127-eca11ab3bbca

And the Dockerfile:

FROM ligato/vpp-agent:latest as go
ondrej-fabry commented 4 years ago

vppagent version from the go.mod:

go.ligato.io/vpp-agent/v3 v3.2.0-alpha.0.20201016122127-eca11ab3bbca

This should not really matter as you only use vpp-agent Go module for generated gRPC client and this issue is about server behavior.

And the Dockerfile:

FROM ligato/vpp-agent:latest as go

That is not unique identifier..

To be reference docker image uniquely, use Digest (or RepoDigest) that shows up in docker inspect <image> or when in output of docker pull:

Digest: sha256:d11256b24c296117cdce33382571c7525bd4f6d76066b327229e051679a3ac93

Or even better would be to copy this part of the log with logo:

                                       __
  _  _____  ___ _______ ____ ____ ___ / /_  
 | |/ / _ \/ _ /___/ _ '/ _ '/ -_/ _ / __/  vpp-agent v3.2.0-alpha-75-geca11ab3b
 |___/ .__/ .__/   \_'_/\_' /\__/_//_\__/   Fri Oct 16 12:21:57 UTC 2020 (6 minutes ago)
    /_/  /_/           /___/                root@97d8490f6cf1 (go1.15.2 linux/amd64)
edwarnicke commented 4 years ago 
                                       __
  _  _____  ___ _______ ____ ____ ___ / /_  
 | |/ / _ \/ _ /___/ _ '/ _ '/ -_/ _ / __/  vpp-agent v3.2.0-alpha-67-g0ead9d2f7
 |___/ .__/ .__/   \_'_/\_' /\__/_//_\__/   Mon Oct  5 11:47:39 UTC 2020 (15 days ago)
    /_/  /_/           /___/                root@c4b52bfc2c26 (go1.15.2 linux/amd64)
ondrej-fabry commented 4 years ago

Please update your image you seem to have older version that did not have the fix: https://github.com/ligato/vpp-agent/commit/67667869cf84a7cbf0ff115ef9db8076406d8320

edwarnicke commented 4 years ago

Updated images and a few observations:

  1. I am not obviously seeing the interface up issue, but need to beat on it a bit more (its a race condition) to be certain.
  2. I do appear to be seeing 'the routes aren't programmed in the namespace' as an issue... is that something we should open a new issue for?
  3. Much much faster... except on startup where there are still some issues apparent. Will marshal more data for you on that.
ondrej-fabry commented 4 years ago

Updated images and a few observations:

1. I am not obviously seeing the interface up issue, but need to beat on it a bit more (its a race condition) to be certain.

Tracked in https://github.com/ligato/vpp-agent/issues/1751

2. I _do_ appear to be seeing 'the routes aren't programmed in the namespace' as an issue... is that something we should open a new issue for?

Yes, open new issue please.

3. Much much faster... except on startup where there are still some issues apparent.  Will marshal more data for you on that.

Kinda tracked in https://github.com/ligato/vpp-agent/issues/1749

ondrej-fabry commented 4 years ago

Can I close this issue? Other problems are unrelated to this issue of "WaitDone taking ~500ms.." and should be tracked separately.

edwarnicke commented 4 years ago

Don't close quite yet, need to beat on it a bit more to be sure.