GitHub pull request #2244 of commit 6be367d569db43275c9a7074a984a8d1b35c284b, no merge conflicts. Running as SYSTEM Setting status of 6be367d569db43275c9a7074a984a8d1b35c284b to PENDING with url http://vps736962.ovh.net:8080/job/skydive-functional-tests-backend-elasticsearch/421/ and message: 'Build started for merge commit.' Using context: skydive-functional-tests-backend-elasticsearch Setting status of 6be367d569db43275c9a7074a984a8d1b35c284b to PENDING with url http://ci-logs.skydive.network/logs/skydive-functional-tests-backend-elasticsearch/421 and message: 'Build started for merge commit.' Using context: skydive-functional-tests-backend-elasticsearch [EnvInject] - Loading node environment variables. [EnvInject] - Preparing an environment for the build. [EnvInject] - Keeping Jenkins system variables. [EnvInject] - Keeping Jenkins build variables. [EnvInject] - Injecting as environment variables the properties content MINIKUBE_DRIVER=virtualbox [EnvInject] - Variables injected successfully. [EnvInject] - Injecting contributions. Building remotely on ha:////4P4aje/6DECeLZptqtyVZ6ZKF5vnXJrCPTSxhrP4t01JAAAAoR+LCAAAAAAAAP9b85aBtbiIQTGjNKU4P08vOT+vOD8nVc83PyU1x6OyILUoJzMv2y+/JJUBAhiZGBgqihhk0NSjKDWzXb3RdlLBUSYGJk8GtpzUvPSSDB8G5tKinBIGIZ+sxLJE/ZzEvHT94JKizLx0a6BxUmjGOUNodHsLgAzuEgZR/eT83ILSktQi/cykXN3inMSyVF0jAAAahufKAAAAibm-slave-2 (baremetal slaves vagrant) in workspace /var/lib/jenkins/workspace/skydive-functional-tests-backend-elasticsearch No credentials specified Wiping out workspace first. Cloning the remote Git repository Cloning repository https://github.com/skydive-project/skydive > git init /var/lib/jenkins/workspace/skydive-functional-tests-backend-elasticsearch/src/github.com/skydive-project/skydive # timeout=10 Fetching upstream changes from https://github.com/skydive-project/skydive > git --version # timeout=10 > git fetch --tags --force --progress -- https://github.com/skydive-project/skydive +refs/heads/*:refs/remotes/origin/* # timeout=20 > git config remote.origin.url https://github.com/skydive-project/skydive # timeout=10 > git config --add remote.origin.fetch +refs/heads/*:refs/remotes/origin/* # timeout=10 > git config remote.origin.url https://github.com/skydive-project/skydive # timeout=10 Fetching upstream changes from https://github.com/skydive-project/skydive > git fetch --tags --force --progress -- https://github.com/skydive-project/skydive +refs/pull/*:refs/remotes/origin/pr/* # timeout=20 > git rev-parse refs/remotes/origin/pr/2244/merge^{commit} # timeout=10 > git rev-parse refs/remotes/origin/origin/pr/2244/merge^{commit} # timeout=10 Checking out Revision 2dba1626acb536c69573b8e9d150b7eadeb6cf03 (refs/remotes/origin/pr/2244/merge) > git config core.sparsecheckout # timeout=10 > git checkout -f 2dba1626acb536c69573b8e9d150b7eadeb6cf03 # timeout=20 Commit message: "Merge 6be367d569db43275c9a7074a984a8d1b35c284b into 81fc5b039256c126af399ab28db9ed041037e315" First time build. Skipping changelog. No credentials specified Wiping out workspace first. Cloning the remote Git repository Cloning repository https://github.com/skydive-project/skydive-ci > git init /var/lib/jenkins/workspace/skydive-functional-tests-backend-elasticsearch/src/github.com/skydive-project/skydive-ci # timeout=10 Fetching upstream changes from https://github.com/skydive-project/skydive-ci > git --version # timeout=10 > git fetch --tags --force --progress -- https://github.com/skydive-project/skydive-ci +refs/heads/*:refs/remotes/origin/* # timeout=20 > git config remote.origin.url https://github.com/skydive-project/skydive-ci # timeout=10 > git config --add remote.origin.fetch +refs/heads/*:refs/remotes/origin/* # timeout=10 > git config remote.origin.url https://github.com/skydive-project/skydive-ci # timeout=10 Fetching upstream changes from https://github.com/skydive-project/skydive-ci > git fetch --tags --force --progress -- https://github.com/skydive-project/skydive-ci +refs/heads/*:refs/remotes/origin/* # timeout=20 > git rev-parse origin/master^{commit} # timeout=10 Checking out Revision a9f0be3c8ca7b7de11f103115118de3c21116b6d (origin/master) > git config core.sparsecheckout # timeout=10 > git checkout -f a9f0be3c8ca7b7de11f103115118de3c21116b6d # timeout=20 Commit message: "Run Skydive scale.sh stop only for scale tests cleanup" > git rev-list --no-walk a9f0be3c8ca7b7de11f103115118de3c21116b6d # timeout=10 [skydive-functional-tests-backend-elasticsearch] $ /bin/bash /tmp/jenkins6426509043672234064.sh agent-1 agent-1-vm1 agent-1-vm2 agent-2 agent-2-vm1 agent-2-vm2 agent-3 agent-3-vm1 agent-3-vm2 agent-4 agent-4-vm1 agent-4-vm2 agent-1-eth0 agent-2-eth0 agent-3-eth0 agent-4-eth0 br-central docker0 eno1 eno2 eno3 eno4 eno5 eno6 erspan0 gre0 gretap0 lo lxdbr0 vboxnet0 vethfdc98ca 421bb3a193e0 VOLUME NAME /usr/bin/minikube ! "minikube" cluster does not exist ! "minikube" profile does not exist Deleted Images: untagged: elasticsearch:7.7.1 untagged: elasticsearch@sha256:dff614393a31b93e8bbe9f8d1a77be041da37eac2a7a9567166dd5a2abab7c67 deleted: sha256:830a894845e39d20e413d8a824ba1f7562d76a02cf9a85a8b6d1d9d47a4d5dd3 deleted: sha256:2e81b12ba75f8aaf2c9f14cc6ed81b2761b89602c689debcfcdc9f51531cf836 deleted: sha256:3fd0f0214ec359cf53e77af8281aa353d1f3e06e145bbff6fca0db95654f8424 deleted: sha256:bfc410831cfe7aa270b31428000371f29172eb4bdf838ac318973e0623dc4cd0 deleted: sha256:92dbfaec982adaa220fbd4302a1c24351b0d8a69cba6ca69d29d9a9f56e6eb5d deleted: sha256:7361e84d230e71ab9dc597421578e4cd9f4359f2d9d83031030054b9a7d05e91 deleted: sha256:08054599c6222569217af7815b11fc3f666f8a8c0d63cbb4eabe8f5921cb9a5f deleted: sha256:55c2b32bf60bd1677b4cc729c96cf61eb4d9eda24f027be06860ef4eda79931b deleted: sha256:d0e2341f56f8b2717ba82d7645a209fda293584e0b864ca8fa49e77f85e8a368 deleted: sha256:edf3aa290fb3c255a84fe836109093fbfeef65c08544f655fad8d6afb53868ba untagged: skydive/ebpf-builder:latest untagged: skydive/ebpf-builder@sha256:5b52e9dce04a32b0644426da33d6352451831f29a1967813c13760d2457a3e9d deleted: sha256:a5e3dc234e783cc79313b345a6dea20377e2b18f23f95ca8d1ab7ce31e9bb798 deleted: sha256:5aca5d753f9e7e17ce76781b4b88650e4d7bbc9d85869857a10c0a0a4b43982d deleted: sha256:fe17f2ed86269a12ee4f30df6a2f385cd1d20d15d6f993062cf084e4f92d125c Total reclaimed space: 2.361GB Failed to stop localkube.service: Unit localkube.service not loaded. Failed to disable unit: Unit file localkube.service does not exist. RTNETLINK answers: Operation not supported 421bb3a193e0 421bb3a193e0 + check_dependencies ++ which inotifywait + '[' '!' /usr/bin/inotifywait ']' ++ which realpath + '[' '!' /usr/bin/realpath ']' + '[' stop == start ']' + '[' stop == stop ']' + '[' -z 2 ']' + stop 2 4 2 + ANALYZER_NUM=2 + AGENT_NUM=4 + VM_NUM=2 + echo 'Stopping Agents...' Stopping Agents... ++ seq 4 + for A in $( seq $AGENT_NUM ) + stop_agent 1 + AGENT=1 + NAME=agent-1 + '[' -e /tmp/skydive-scale/agent-1.pid ']' + sudo pkill -f agent-1.yml + timeout=30 + pkill -0 -f agent-1.yml + sudo rm -f /tmp/skydive-scale/agent-1.lock /tmp/skydive-scale/agent-1.pid + for A in $( seq $AGENT_NUM ) + stop_agent 2 + AGENT=2 + NAME=agent-2 + '[' -e /tmp/skydive-scale/agent-2.pid ']' + sudo pkill -f agent-2.yml + timeout=30 + pkill -0 -f agent-2.yml + sudo rm -f /tmp/skydive-scale/agent-2.lock /tmp/skydive-scale/agent-2.pid + for A in $( seq $AGENT_NUM ) + stop_agent 3 + AGENT=3 + NAME=agent-3 + '[' -e /tmp/skydive-scale/agent-3.pid ']' + sudo pkill -f agent-3.yml + timeout=30 + pkill -0 -f agent-3.yml + sudo rm -f /tmp/skydive-scale/agent-3.lock /tmp/skydive-scale/agent-3.pid + for A in $( seq $AGENT_NUM ) + stop_agent 4 + AGENT=4 + NAME=agent-4 + '[' -e /tmp/skydive-scale/agent-4.pid ']' + sudo pkill -f agent-4.yml + timeout=30 + pkill -0 -f agent-4.yml + sudo rm -f /tmp/skydive-scale/agent-4.lock /tmp/skydive-scale/agent-4.pid + echo 'Stopping Analyzers...' Stopping Analyzers... ++ seq 2 + for A in $( seq $ANALYZER_NUM ) + stop_analyzer 1 + ANALYZER=1 + NAME=analyzer-1 + '[' -e /tmp/skydive-scale/analyzer-1.pid ']' + sudo pkill -f analyzer-1.yml + timeout=30 + pkill -0 -f analyzer-1.yml + sudo rm -f /tmp/skydive-scale/analyzer-1.lock /tmp/skydive-scale/analyzer-1.pid + for A in $( seq $ANALYZER_NUM ) + stop_analyzer 2 + ANALYZER=2 + NAME=analyzer-2 + '[' -e /tmp/skydive-scale/analyzer-2.pid ']' + sudo pkill -f analyzer-2.yml + timeout=30 + pkill -0 -f analyzer-2.yml + sudo rm -f /tmp/skydive-scale/analyzer-2.lock /tmp/skydive-scale/analyzer-2.pid + sleep 5 + sudo -E screen -S skydive-stress -X quit + rm -f /tmp/skydive-scale/screen.lock ++ seq 4 + for AGENT_I in $( seq $AGENT_NUM ) + delete_agent 1 2 + IDX=1 + VM_NUM=2 + NAME=agent-1 + echo Delete agent agent-1 Delete agent agent-1 + '[' -f /tmp/skydive-scale/agent-1-vswitchd.pid ']' ++ cat /tmp/skydive-scale/agent-1-vswitchd.pid + sudo kill -9 20357 + '[' -f /tmp/skydive-scale/agent-1-dbserver.pid ']' ++ cat /tmp/skydive-scale/agent-1-dbserver.pid + sudo kill -9 20352 ++ seq 2 + for VM_I in $( seq $VM_NUM ) + sudo ip netns pids agent-1-vm1 + for VM_I in $( seq $VM_NUM ) + sudo ip netns pids agent-1-vm2 + rm -f /tmp/skydive-scale/agent-1.lock + delete_host agent-1 + NAME=agent-1 + echo Delete Host agent-1 Delete Host agent-1 + sudo ovs-vsctl get Port agent-1-eth0 + sudo ip link show agent-1-eth0 + sudo ip netns pids agent-1 + for AGENT_I in $( seq $AGENT_NUM ) + delete_agent 2 2 + IDX=2 + VM_NUM=2 + NAME=agent-2 + echo Delete agent agent-2 Delete agent agent-2 + '[' -f /tmp/skydive-scale/agent-2-vswitchd.pid ']' ++ cat /tmp/skydive-scale/agent-2-vswitchd.pid + sudo kill -9 20552 + '[' -f /tmp/skydive-scale/agent-2-dbserver.pid ']' ++ cat /tmp/skydive-scale/agent-2-dbserver.pid + sudo kill -9 20546 ++ seq 2 + for VM_I in $( seq $VM_NUM ) + sudo ip netns pids agent-2-vm1 + for VM_I in $( seq $VM_NUM ) + sudo ip netns pids agent-2-vm2 + rm -f /tmp/skydive-scale/agent-2.lock + delete_host agent-2 + NAME=agent-2 + echo Delete Host agent-2 Delete Host agent-2 + sudo ovs-vsctl get Port agent-2-eth0 + sudo ip link show agent-2-eth0 + sudo ip netns pids agent-2 + for AGENT_I in $( seq $AGENT_NUM ) + delete_agent 3 2 + IDX=3 + VM_NUM=2 + NAME=agent-3 + echo Delete agent agent-3 Delete agent agent-3 + '[' -f /tmp/skydive-scale/agent-3-vswitchd.pid ']' ++ cat /tmp/skydive-scale/agent-3-vswitchd.pid + sudo kill -9 20748 + '[' -f /tmp/skydive-scale/agent-3-dbserver.pid ']' ++ cat /tmp/skydive-scale/agent-3-dbserver.pid + sudo kill -9 20741 ++ seq 2 + for VM_I in $( seq $VM_NUM ) + sudo ip netns pids agent-3-vm1 + for VM_I in $( seq $VM_NUM ) + sudo ip netns pids agent-3-vm2 + rm -f /tmp/skydive-scale/agent-3.lock + delete_host agent-3 + NAME=agent-3 + echo Delete Host agent-3 Delete Host agent-3 + sudo ovs-vsctl get Port agent-3-eth0 + sudo ip link show agent-3-eth0 + sudo ip netns pids agent-3 + for AGENT_I in $( seq $AGENT_NUM ) + delete_agent 4 2 + IDX=4 + VM_NUM=2 + NAME=agent-4 + echo Delete agent agent-4 Delete agent agent-4 + '[' -f /tmp/skydive-scale/agent-4-vswitchd.pid ']' ++ cat /tmp/skydive-scale/agent-4-vswitchd.pid + sudo kill -9 20938 + '[' -f /tmp/skydive-scale/agent-4-dbserver.pid ']' ++ cat /tmp/skydive-scale/agent-4-dbserver.pid + sudo kill -9 20933 ++ seq 2 + for VM_I in $( seq $VM_NUM ) + sudo ip netns pids agent-4-vm1 + for VM_I in $( seq $VM_NUM ) + sudo ip netns pids agent-4-vm2 + rm -f /tmp/skydive-scale/agent-4.lock + delete_host agent-4 + NAME=agent-4 + echo Delete Host agent-4 Delete Host agent-4 + sudo ovs-vsctl get Port agent-4-eth0 + sudo ip link show agent-4-eth0 + sudo ip netns pids agent-4 + delete_main_bridge + echo Delete central bridge Delete central bridge + sudo ip link del br-central Cannot find device "br-central" + sudo find /tmp/skydive-scale -mindepth 1 '!' -name '*.log' -a '!' -name '*.cover' -exec rm -rf '{}' ';' find: ‘/tmp/skydive-scale/agent-4-netns’: No such file or directory find: ‘/tmp/skydive-scale/agent-3-netns’: No such file or directory find: ‘/tmp/skydive-scale/agent-2-netns’: No such file or directory find: ‘/tmp/skydive-scale/agent-1-netns’: No such file or directory find: ‘/tmp/skydive-scale/analyzer-1-etcd’: No such file or directory % Total % Received % Xferd Average Speed Time Time Time Current Dload Upload Total Spent Left Speed 0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0 100 21 100 21 0 0 41 0 --:--:-- --:--:-- --:--:-- 41 {"acknowledged":true}Failed to stop etcd.service: Unit etcd.service not loaded. OrientDB console v.3.0.19 - Veloce (build 5d85f6d68158f0e375f4764f7eee5b02a5e1900b, branch 3.0.x) https://www.orientdb.com Type 'help' to display all the supported commands. Connecting to database [remote:localhost/Skydive] with user 'root'... Error: com.orientechnologies.orient.core.exception.ODatabaseException: Cannot open database 'Skydive' Error: com.orientechnologies.orient.core.exception.ODatabaseException: Cannot open database 'Skydive' Error: com.orientechnologies.orient.core.exception.OStorageException: Cannot open the storage 'Skydive' because it does not exist in path: /opt/orientdb-3.0.19/databases/Skydive error: failed to get domain 'dev_dev' error: failed to get domain 'dev_dev' error: failed to get vol 'dev_dev.img' error: Storage volume not found: no storage vol with matching path 'dev_dev.img' error: failed to get domain 'vagrant_analyzer1' error: failed to get domain 'vagrant_analyzer1' error: failed to get vol 'vagrant_analyzer1.img' error: Storage volume not found: no storage vol with matching path 'vagrant_analyzer1.img' error: failed to get domain 'vagrant_agent1' error: failed to get domain 'vagrant_agent1' error: failed to get vol 'vagrant_agent1.img' error: Storage volume not found: no storage vol with matching path 'vagrant_agent1.img' error: failed to get domain 'devstack_devstack' error: failed to get domain 'devstack_devstack' error: failed to get vol 'devstack_devstack.img' error: Storage volume not found: no storage vol with matching path 'devstack_devstack.img' error: failed to get network 'vagrant0' error: Network not found: no network with matching name 'vagrant0' error: Failed to destroy network vagrant-libvirt error: Requested operation is not valid: network 'vagrant-libvirt' is not active [skydive-functional-tests-backend-elasticsearch] $ /bin/sh -xe /tmp/jenkins7534854734667732198.sh + set -v #!/bin/bash cd src/github.com/skydive-project/skydive + cd src/github.com/skydive-project/skydive # Set Environment echo $PATH | grep -q "$HOME/bin" || export PATH="$PATH:$HOME/bin" + echo /usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin + grep -q /var/lib/jenkins/bin + export PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/var/lib/jenkins/bin + PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/var/lib/jenkins/bin # Install Go mkdir -p ~/bin + mkdir -p /var/lib/jenkins/bin curl -sL -o ~/bin/gimme https://raw.githubusercontent.com/travis-ci/gimme/master/gimme + curl -sL -o /var/lib/jenkins/bin/gimme https://raw.githubusercontent.com/travis-ci/gimme/master/gimme chmod +x ~/bin/gimme + chmod +x /var/lib/jenkins/bin/gimme # before changing this be sure that it will not break the RHEL packaging eval "$(gimme 1.11.13)" ++ gimme 1.11.13 + eval ' unset GOOS; unset GOARCH; export GOROOT='\''/var/lib/jenkins/.gimme/versions/go1.11.13.linux.amd64'\''; export PATH="/var/lib/jenkins/.gimme/versions/go1.11.13.linux.amd64/bin:${PATH}"; go version >&2; export GIMME_ENV='\''/var/lib/jenkins/.gimme/envs/go1.11.13.linux.amd64.env'\'';' unset GOOS; ++ unset GOOS unset GOARCH; ++ unset GOARCH export GOROOT='/var/lib/jenkins/.gimme/versions/go1.11.13.linux.amd64'; ++ export GOROOT=/var/lib/jenkins/.gimme/versions/go1.11.13.linux.amd64 ++ GOROOT=/var/lib/jenkins/.gimme/versions/go1.11.13.linux.amd64 export PATH="/var/lib/jenkins/.gimme/versions/go1.11.13.linux.amd64/bin:${PATH}"; ++ export PATH=/var/lib/jenkins/.gimme/versions/go1.11.13.linux.amd64/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/var/lib/jenkins/bin ++ PATH=/var/lib/jenkins/.gimme/versions/go1.11.13.linux.amd64/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/var/lib/jenkins/bin go version >&2; ++ go version go version go1.11.13 linux/amd64 export GIMME_ENV='/var/lib/jenkins/.gimme/envs/go1.11.13.linux.amd64.env'; ++ export GIMME_ENV=/var/lib/jenkins/.gimme/envs/go1.11.13.linux.amd64.env ++ GIMME_ENV=/var/lib/jenkins/.gimme/envs/go1.11.13.linux.amd64.env export GO111MODULE=on + export GO111MODULE=on + GO111MODULE=on export GOPATH=$WORKSPACE + export GOPATH=/var/lib/jenkins/workspace/skydive-functional-tests-backend-elasticsearch + GOPATH=/var/lib/jenkins/workspace/skydive-functional-tests-backend-elasticsearch export PATH=$PATH:$GOPATH/bin + export PATH=/var/lib/jenkins/.gimme/versions/go1.11.13.linux.amd64/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/var/lib/jenkins/bin:/var/lib/jenkins/workspace/skydive-functional-tests-backend-elasticsearch/bin + PATH=/var/lib/jenkins/.gimme/versions/go1.11.13.linux.amd64/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/var/lib/jenkins/bin:/var/lib/jenkins/workspace/skydive-functional-tests-backend-elasticsearch/bin # share compile cache mkdir -p $HOME/pkg + mkdir -p /var/lib/jenkins/pkg rm -rf $GOPATH/pkg + rm -rf /var/lib/jenkins/workspace/skydive-functional-tests-backend-elasticsearch/pkg ln -s $HOME/pkg $GOPATH/pkg + ln -s /var/lib/jenkins/pkg /var/lib/jenkins/workspace/skydive-functional-tests-backend-elasticsearch/pkg [[ "$ghprbCommentBody" = *"insanelock"* ]] && export TAGS=mutexdebug + [[ null = *\i\n\s\a\n\e\l\o\c\k* ]] [[ "$ghprbCommentBody" = *"profile"* ]] && export WITH_PROF=true + [[ null = *\p\r\o\f\i\l\e* ]] [[ "$ghprbPullLongDescription" = *"pattern="* ]] && export TEST_PATTERN=`expr match "$ghprbPullLongDescription" '^.*pattern=\(.*\)$'` + [[ '' = *\p\a\t\t\e\r\n\=* ]] [[ "$ghprbCommentBody" = *"pattern="* ]] && export TEST_PATTERN=`expr match "$ghprbCommentBody" '^.*pattern=\(.*\)$'` + [[ null = *\p\a\t\t\e\r\n\=* ]] BACKEND=elasticsearch WITH_EBPF=true ARGS="-ovs.oflow.native" scripts/ci/run-functional-tests.sh + BACKEND=elasticsearch + WITH_EBPF=true + ARGS=-ovs.oflow.native + scripts/ci/run-functional-tests.sh set -e DIR="$(dirname "$0")" . "$DIR/run-tests-utils.sh" network_setup() { sudo iptables -F sudo iptables -P FORWARD ACCEPT for i in $(find /proc/sys/net/bridge/ -type f); do echo 0 | sudo tee $i done } mem_prof() { echo start memory profiling while(true); do echo trigger memory profiling snapshot sudo pkill -USR2 functionals 2>/dev/null || true sleep 10 sudo mv /tmp/skydive-memory.prof /tmp/skydive-memory.prof.$( date +%T ) 2>/dev/null || true done } es_setup() { docker run -d --name elasticsearch -p 9201:9200 -p 9301:9300 -e "discovery.type=single-node" elasticsearch:7.7.1 } es_cleanup() { docker stop elasticsearch docker rm elasticsearch } tests_run() { cd ${GOPATH}/src/github.com/skydive-project/skydive if [ -z "$WORKSPACE" ]; then echo "need to define WORKSPACE before running script" exit 1 fi LOGFILE=$WORKSPACE/output.log TESTFILE=$WORKSPACE/tests.xml BACKEND=${BACKEND:-memory} if [ "$BACKEND" = "elasticsearch" ]; then es_setup && trap es_cleanup EXIT fi ARGS="$ARGS -standalone -analyzer.topology.backend $BACKEND -analyzer.flow.backend $BACKEND" export ORIENTDB_ROOT_PASSWORD=root if [ "$COVERAGE" != "true" -a "$(uname -m)" != "ppc64le" ]; then export TEST_COVERPROFILE=../functionals-$BACKEND.cover fi if [ "$WITH_PROF" = "true" ]; then mem_prof& MEMPROFPID=$! fi make test.functionals.batch \ GOFLAGS="$GOFLAGS" VERBOSE=true TAGS="$TAGS" GORACE="history_size=7" TIMEOUT=20m \ WITH_HELM="$WITH_HELM" WITH_EBPF="$WITH_EBPF" WITH_EBPF_DOCKER_BUILDER=true \ WITH_K8S="$WITH_K8S" WITH_ISTIO="$WITH_ISTIO" \ WITH_PROF="$WITH_PROF" ARGS="$ARGS" TEST_PATTERN="$TEST_PATTERN" 2>&1 | tee $LOGFILE RETCODE=$? if [ "$WITH_PROF" = "true" ]; then kill $MEMPROFPID 2>/dev/null fi go get -f -u github.com/tebeka/go2xunit go2xunit -fail -fail-on-race -suite-name-prefix tests \ -input $LOGFILE -output $TESTFILE sed -i 's/\x1b\[[0-9;]*m//g' $TESTFILE if [ -e functionals.cover ]; then mv functionals.cover $TEST_COVERPROFILE fi } network_setup 0 0 0 0 0 0 WITH_OVN=true WITH_OPENCONTRAIL=false tests_run Unable to find image 'elasticsearch:7.7.1' locally 7.7.1: Pulling from library/elasticsearch 524b0c1e57f8: Pulling fs layer 4f79045bc94a: Pulling fs layer 4602c5830f92: Pulling fs layer 10ef2eb1c9b1: Pulling fs layer 47fca9194a1b: Pulling fs layer c282e1371ecc: Pulling fs layer 302e1effd34b: Pulling fs layer 50acbec75309: Pulling fs layer f89bc5c60b5f: Pulling fs layer 47fca9194a1b: Waiting c282e1371ecc: Waiting 10ef2eb1c9b1: Waiting 50acbec75309: Waiting 302e1effd34b: Waiting f89bc5c60b5f: Waiting 4f79045bc94a: Download complete 4602c5830f92: Verifying Checksum 4602c5830f92: Download complete 10ef2eb1c9b1: Verifying Checksum 10ef2eb1c9b1: Download complete 524b0c1e57f8: Verifying Checksum 524b0c1e57f8: Download complete c282e1371ecc: Verifying Checksum c282e1371ecc: Download complete 302e1effd34b: Verifying Checksum 302e1effd34b: Download complete 50acbec75309: Verifying Checksum 50acbec75309: Download complete f89bc5c60b5f: Verifying Checksum f89bc5c60b5f: Download complete 524b0c1e57f8: Pull complete 4f79045bc94a: Pull complete 4602c5830f92: Pull complete 47fca9194a1b: Verifying Checksum 47fca9194a1b: Download complete 10ef2eb1c9b1: Pull complete 47fca9194a1b: Pull complete c282e1371ecc: Pull complete 302e1effd34b: Pull complete 50acbec75309: Pull complete f89bc5c60b5f: Pull complete Digest: sha256:dff614393a31b93e8bbe9f8d1a77be041da37eac2a7a9567166dd5a2abab7c67 Status: Downloaded newer image for elasticsearch:7.7.1 84963e9fdd4a5eb00239c3521a6352c47ec0d504db9295e08dbb8075f7fdc7b9 go mod download go: finding github.com/networkservicemesh/networkservicemesh/controlplane v0.2.0 go: finding github.com/networkservicemesh/networkservicemesh/dataplane/api v0.2.0 go: finding github.com/networkservicemesh/networkservicemesh/k8s/api v0.2.0 go: finding k8s.io/api v0.0.0 go: finding k8s.io/apiextensions-apiserver v0.0.0 go: finding k8s.io/apimachinery v0.0.0 go: finding k8s.io/apiserver v0.0.0 go: finding k8s.io/cli-runtime v0.0.0 go: finding k8s.io/cloud-provider v0.0.0 go: finding k8s.io/cluster-bootstrap v0.0.0 go: finding k8s.io/code-generator v0.0.0 go: finding k8s.io/component-base v0.0.0 go: finding k8s.io/cri-api v0.0.0 go: finding k8s.io/csi-translation-lib v0.0.0 go: finding k8s.io/kube-aggregator v0.0.0 go: finding k8s.io/kube-controller-manager v0.0.0 go: finding k8s.io/kube-proxy v0.0.0 go: finding k8s.io/kube-scheduler v0.0.0 go: finding k8s.io/kubelet v0.0.0 go: finding k8s.io/legacy-cloud-providers v0.0.0 go: finding k8s.io/metrics v0.0.0 go: finding k8s.io/sample-apiserver v0.0.0 make -C ebpf docker-ebpf-build make[1]: Entering directory '/var/lib/jenkins/workspace/skydive-functional-tests-backend-elasticsearch/src/github.com/skydive-project/skydive/ebpf' docker pull skydive/ebpf-builder:latest latest: Pulling from skydive/ebpf-builder 9908e4690737: Pulling fs layer 97c1471f7aa4: Pulling fs layer 9908e4690737: Verifying Checksum 9908e4690737: Download complete 9908e4690737: Pull complete 97c1471f7aa4: Verifying Checksum 97c1471f7aa4: Download complete 97c1471f7aa4: Pull complete Digest: sha256:5b52e9dce04a32b0644426da33d6352451831f29a1967813c13760d2457a3e9d Status: Downloaded newer image for skydive/ebpf-builder:latest docker.io/skydive/ebpf-builder:latest docker run --rm \ --env=UID=1002 \ --env=GID=1004 \ --env=GOPATH=/go \ -v /var/lib/jenkins/workspace/skydive-functional-tests-backend-elasticsearch:/go \ -v /var/lib/jenkins/workspace/skydive-functional-tests-backend-elasticsearch/pkg:/go/pkg \ --workdir=/go/src/github.com/skydive-project/skydive/ebpf \ skydive/ebpf-builder \ sh -c "make ebpf-build && chown -R 1002:1004 ." clang \ -I${GOPATH}/pkg/mod/github.com/iovisor/gobpf@v0.0.0-20200329161226-8b2cce9dac28/elf/include \ -D__KERNEL__ -D__ASM_SYSREG_H -D__TARGET_ARCH_BPF -Wno-unused-value -Wno-pointer-sign \ -Wno-compare-distinct-pointer-types \ -Wno-gnu-variable-sized-type-not-at-end \ -Wno-address-of-packed-member -Wno-tautological-compare \ -Wno-compare-distinct-pointer-types -Wno-unknown-warning-option \ -fno-stack-protector \ -fno-jump-tables \ -fno-common \ -O2 -g -emit-llvm -c flow-gre.c -o ebpf.bc llc -march=bpf -filetype=obj -mattr=dwarfris -o flow-gre.o ebpf.bc rm -f ebpf.bc clang \ -I${GOPATH}/pkg/mod/github.com/iovisor/gobpf@v0.0.0-20200329161226-8b2cce9dac28/elf/include \ -D__KERNEL__ -D__ASM_SYSREG_H -D__TARGET_ARCH_BPF -Wno-unused-value -Wno-pointer-sign \ -Wno-compare-distinct-pointer-types \ -Wno-gnu-variable-sized-type-not-at-end \ -Wno-address-of-packed-member -Wno-tautological-compare \ -Wno-compare-distinct-pointer-types -Wno-unknown-warning-option \ -fno-stack-protector \ -fno-jump-tables \ -fno-common \ -O2 -g -emit-llvm -c flow.c -o ebpf.bc llc -march=bpf -filetype=obj -mattr=dwarfris -o flow.o ebpf.bc rm -f ebpf.bc make[1]: Leaving directory '/var/lib/jenkins/workspace/skydive-functional-tests-backend-elasticsearch/src/github.com/skydive-project/skydive/ebpf' go get github.com/gogo/protobuf/protoc-gen-gogofaster@v1.3.1 go: finding github.com/gogo/protobuf/protoc-gen-gogofaster v1.3.1 go get github.com/golang/protobuf/protoc-gen-go@v1.3.2 go: finding github.com/golang/protobuf/protoc-gen-go v1.3.2 protoc -I. -Iflow/layers -I${GOPATH}/pkg/mod/github.com/gogo/protobuf@v1.3.1 --plugin=${GOPATH}/bin/protoc-gen-gogofaster --gogofaster_out $GOPATH/src flow/flow.proto # always export flow.ParentUUID as we need to store this information to know # if it's a Outer or Inner packet. sed -e 's/ParentUUID\(.*\),omitempty\(.*\)/ParentUUID\1\2/' \ -e 's/Protocol\(.*\),omitempty\(.*\)/Protocol\1\2/' \ -e 's/ICMPType\(.*\),omitempty\(.*\)/ICMPType\1\2/' \ -e 's/int64\(.*\),omitempty\(.*\)/int64\1\2/' \ -i flow/flow.pb.go # add omitempty to RTT as it is not always filled sed -e 's/json:"RTT"/json:"RTT,omitempty"/' -i flow/flow.pb.go # do not export LastRawPackets used internally sed -e 's/json:"LastRawPackets,omitempty"/json:"-"/g' -i flow/flow.pb.go # add flowState to flow generated struct sed -e 's/type Flow struct {/type Flow struct { XXX_state flowState `json:"-"`/' -i flow/flow.pb.go # to fix generated layers import sed -e 's/layers "flow\/layers"/layers "github.com\/skydive-project\/skydive\/flow\/layers"/' -i flow/flow.pb.go sed -e 's/type FlowMetric struct {/\/\/ gendecoder\ntype FlowMetric struct {/' -i flow/flow.pb.go sed -e 's/type FlowLayer struct {/\/\/ gendecoder\ntype FlowLayer struct {/' -i flow/flow.pb.go sed -e 's/type TransportLayer struct {/\/\/ gendecoder\ntype TransportLayer struct {/' -i flow/flow.pb.go sed -e 's/type ICMPLayer struct {/\/\/ gendecoder\ntype ICMPLayer struct {/' -i flow/flow.pb.go sed -e 's/type IPMetric struct {/\/\/ gendecoder\ntype IPMetric struct {/' -i flow/flow.pb.go sed -e 's/type TCPMetric struct {/\/\/ gendecoder\ntype TCPMetric struct {/' -i flow/flow.pb.go # This is to allow calling go generate on flow/flow.pb.go sed -e 's/DO NOT EDIT./DO NOT MODIFY/' -i flow/flow.pb.go sed '1 i //go:generate go run github.com/skydive-project/skydive/graffiti/gendecoder' -i flow/flow.pb.go gofmt -s -w flow/flow.pb.go go get github.com/gogo/protobuf/protoc-gen-gogofaster@v1.3.1 go: finding github.com/gogo/protobuf/protoc-gen-gogofaster v1.3.1 go get github.com/golang/protobuf/protoc-gen-go@v1.3.2 go: finding github.com/golang/protobuf/protoc-gen-go v1.3.2 protoc -I. -Iflow/layers -I${GOPATH}/pkg/mod/github.com/gogo/protobuf@v1.3.1 --plugin=${GOPATH}/bin/protoc-gen-gogofaster --gogofaster_out $GOPATH/src graffiti/filters/filters.proto cd js && npm ci && PATH=`npm bin`:$PATH tsc --module commonjs --target ES5 browser.ts added 147 packages in 1.027s cd js && PATH=`npm bin`:$PATH browserify browser.js -o ../statics/js/bundle.js go run github.com/jteeuwen/go-bindata/go-bindata -nometadata -o statics/bindata.go -pkg=statics -ignore=bindata.go js/*.js rbac/policy.csv statics/index.html statics/css/* statics/css/themes/*/* statics/fonts/* statics/img/* statics/js/* statics/schemas/* statics/workflows/*.yaml gofmt -w -s statics/bindata.go go run github.com/jteeuwen/go-bindata/go-bindata -nometadata -o ebpf/statics/bindata.go -pkg=statics -ignore=bindata.go ebpf/flow.o ebpf/flow-gre.o gofmt -w -s ebpf/statics/bindata.go go generate -run gendecoder flow/flow.pb.go go run github.com/mailru/easyjson/easyjson -all flow/flow.pb.go go test -tags " ebpf lxd libvirt packetinject test" -race -v -timeout 20m -c -o tests/functionals ./tests/ go: finding k8s.io/apimachinery v0.0.0 go: finding k8s.io/api v0.0.0 go: finding github.com/networkservicemesh/networkservicemesh/controlplane v0.2.0 set -e ; make ARGS="-ovs.oflow.native -standalone -analyzer.topology.backend elasticsearch -analyzer.flow.backend elasticsearch " test.functionals.run EXTRA_ARGS="-analyzer.topology.probes=ovn -agent.topology.probes=" TEST_PATTERN="" make[1]: Entering directory '/var/lib/jenkins/workspace/skydive-functional-tests-backend-elasticsearch/src/github.com/skydive-project/skydive' cd tests && sudo -E ./functionals -test.v -test.run "" -test.timeout 20m -ovs.oflow.native -standalone -analyzer.topology.backend elasticsearch -analyzer.flow.backend elasticsearch -analyzer.topology.probes=ovn -agent.topology.probes= Config: --- http: ws: pong_timeout: 10 analyzers: - 127.0.0.1:64500 analyzer: listen: 0.0.0.0:64500 flow: backend: elasticsearch analyzer_username: admin analyzer_password: password topology: backend: elasticsearch probes: - ovn startup: capture_gremlin: "g.V().Has('Name','startup-vm2')" agent: listen: 0.0.0.0:64499 topology: probes: - ovsdb - blockdev - docker - lxd - lldp - runc - socketinfo - libvirt netlink: metrics_update: 5 lldp: interfaces: - lldp0 metadata: mydict: value: 123 myarrays: integers: - 1 - 2 - 3 bools: - true - true strings: - dog - cat - frog flow: expire: 600 update: 10 ovs: oflow: enable: true native: true address: br-test: tcp:127.0.0.1:16633 storage: orientdb: addr: http://127.0.0.1:2480 database: Skydive username: root password: elasticsearch: host: 127.0.0.1:9201 logging: level: DEBUG syslog: address: /tmp/skydive-test-syslog etcd: data_dir: /tmp/skydive-etcd embedded: true servers: - http://localhost:12379 === RUN TestAlertWebhook 2020-07-06T09:29:41.451+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Model: 2020-07-06T09:29:41.451+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Model: 2020-07-06T09:29:41.451+0300 DEBUG config/rbac.go:54 (*logger).Printf skydivecicd1.sl.cloud9.ibm.com: r.r: sub, obj, act 2020-07-06T09:29:41.452+0300 DEBUG config/rbac.go:54 (*logger).Printf skydivecicd1.sl.cloud9.ibm.com: p.p: sub, obj, act, eft 2020-07-06T09:29:41.452+0300 DEBUG config/rbac.go:54 (*logger).Printf skydivecicd1.sl.cloud9.ibm.com: e.e: some(where (p_eft == allow)) && !some(where (p_eft == deny)) 2020-07-06T09:29:41.452+0300 DEBUG config/rbac.go:54 (*logger).Printf skydivecicd1.sl.cloud9.ibm.com: m.m: g(r_sub, p_sub) && r_obj == p_obj && r_act == p_act 2020-07-06T09:29:41.452+0300 DEBUG config/rbac.go:54 (*logger).Printf skydivecicd1.sl.cloud9.ibm.com: g.g: _, _ 2020-07-06T09:29:41.454+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Role links for: g 2020-07-06T09:29:41.454+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: 2020-07-06T09:29:41.454+0300 INFO analyzer/storage.go:60 newGraphBackendFromConfig skydivecicd1.sl.cloud9.ibm.com: Using elasticsearch (driver elasticsearch) as graph storage backend 2020-07-06T09:29:41.456+0300 INFO plugin/topology.go:47 LoadTopologyPlugins skydivecicd1.sl.cloud9.ibm.com: Topology plugins: [] 2020-07-06T09:29:41.458+0300 INFO analyzer/storage.go:115 newFlowBackendFromConfig skydivecicd1.sl.cloud9.ibm.com: Using elasticsearch (driver elasticsearch) as flow storage backend 2020-07-06T09:29:41.466+0300 INFO server/flow_server.go:217 NewFlowServerUDPConn skydivecicd1.sl.cloud9.ibm.com: Analyzer listen agents on UDP socket 2020-07-06 09:29:41.630390 I | embed: listening for peers on http://127.0.0.1:12380 2020-07-06 09:29:41.630481 I | embed: listening for client requests on 127.0.0.1:12379 2020-07-06 09:29:41.631515 I | etcdserver: name = skydivecicd1.sl.cloud9.ibm.com 2020-07-06 09:29:41.631543 I | etcdserver: data dir = /tmp/skydive-etcd 2020-07-06 09:29:41.631575 I | etcdserver: member dir = /tmp/skydive-etcd/member 2020-07-06 09:29:41.631601 I | etcdserver: heartbeat = 100ms 2020-07-06 09:29:41.631639 I | etcdserver: election = 1000ms 2020-07-06 09:29:41.631668 I | etcdserver: snapshot count = 100000 2020-07-06 09:29:41.631714 I | etcdserver: advertise client URLs = http://127.0.0.1:12379 2020-07-06 09:29:41.631738 I | etcdserver: initial advertise peer URLs = http://localhost:12380 2020-07-06 09:29:41.631768 I | etcdserver: initial cluster = skydivecicd1.sl.cloud9.ibm.com=http://localhost:12380 2020-07-06 09:29:41.639779 I | etcdserver: starting member c9ac9fc89eae9cf7 in cluster f290f7f84a022555 2020-07-06 09:29:41.639836 I | raft: c9ac9fc89eae9cf7 became follower at term 0 2020-07-06 09:29:41.639873 I | raft: newRaft c9ac9fc89eae9cf7 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0] 2020-07-06 09:29:41.639897 I | raft: c9ac9fc89eae9cf7 became follower at term 1 2020-07-06 09:29:41.641301 W | auth: simple token is not cryptographically signed 2020-07-06 09:29:41.641789 I | etcdserver: starting server... [version: 3.3.15, cluster version: to_be_decided] 2020-07-06 09:29:41.642198 I | etcdserver: c9ac9fc89eae9cf7 as single-node; fast-forwarding 9 ticks (election ticks 10) 2020-07-06 09:29:41.643057 I | etcdserver/membership: added member c9ac9fc89eae9cf7 [http://localhost:12380] to cluster f290f7f84a022555 2020-07-06 09:29:42.640376 I | raft: c9ac9fc89eae9cf7 is starting a new election at term 1 2020-07-06 09:29:42.640477 I | raft: c9ac9fc89eae9cf7 became candidate at term 2 2020-07-06 09:29:42.640568 I | raft: c9ac9fc89eae9cf7 received MsgVoteResp from c9ac9fc89eae9cf7 at term 2 2020-07-06 09:29:42.640673 I | raft: c9ac9fc89eae9cf7 became leader at term 2 2020-07-06 09:29:42.640747 I | raft: raft.node: c9ac9fc89eae9cf7 elected leader c9ac9fc89eae9cf7 at term 2 2020-07-06 09:29:42.642168 I | etcdserver: setting up the initial cluster version to 3.3 2020-07-06 09:29:42.643586 N | etcdserver/membership: set the initial cluster version to 3.3 2020-07-06 09:29:42.644005 I | etcdserver/api: enabled capabilities for version 3.3 2020-07-06 09:29:42.644224 I | etcdserver: published {Name:skydivecicd1.sl.cloud9.ibm.com ClientURLs:[http://127.0.0.1:12379]} to cluster f290f7f84a022555 2020-07-06T09:29:42.644+0300 INFO server/server.go:138 (*EmbeddedServer).Start skydivecicd1.sl.cloud9.ibm.com: Server is ready! 2020-07-06 09:29:42.644731 I | embed: ready to serve client requests 2020-07-06 09:29:42.651867 N | embed: serving insecure client requests on 127.0.0.1:12379, this is strongly discouraged! 2020-07-06T09:29:42.654+0300 INFO server/server.go:163 (*EmbeddedServer).Start skydivecicd1.sl.cloud9.ibm.com: Successfully started etcd 2020-07-06T09:29:42.659+0300 INFO client/election.go:105 (*MasterElector).start skydivecicd1.sl.cloud9.ibm.com: starting as the master for /master-analyzer-es-graph-flush: skydivecicd1.sl.cloud9.ibm.com 2020-07-06T09:29:45.966+0300 INFO client/election.go:105 (*MasterElector).start skydivecicd1.sl.cloud9.ibm.com: starting as the master for /master-analyzer-es-rolling-index:35534fa2: skydivecicd1.sl.cloud9.ibm.com 2020-07-06T09:29:45.967+0300 INFO elasticsearch/client.go:235 (*Client).start skydivecicd1.sl.cloud9.ibm.com: client started for skydive_topology_live, skydive_topology_archive 2020-07-06T09:29:45.967+0300 INFO graph/elasticsearch.go:508 (*ElasticSearchBackend).flushGraph skydivecicd1.sl.cloud9.ibm.com: Flush graph elements 2020-07-06T09:29:46.180+0300 DEBUG ovn/ovn.go:469 (*Probe).Do skydivecicd1.sl.cloud9.ibm.com: Trying to get an OVN DB api 2020-07-06T09:29:46.185+0300 INFO client/election.go:105 (*MasterElector).start skydivecicd1.sl.cloud9.ibm.com: starting as the master for /master-analyzer-ondemand-client-Capture: skydivecicd1.sl.cloud9.ibm.com 2020-07-06T09:29:46.192+0300 INFO client/election.go:105 (*MasterElector).start skydivecicd1.sl.cloud9.ibm.com: starting as the master for /master-analyzer-ondemand-client-PacketInjection: skydivecicd1.sl.cloud9.ibm.com 2020-07-06T09:29:46.193+0300 DEBUG ovn/ovn.go:479 (*Probe).Do skydivecicd1.sl.cloud9.ibm.com: Successfully got an OVN DB api 2020-07-06T09:29:46.201+0300 INFO client/election.go:105 (*MasterElector).start skydivecicd1.sl.cloud9.ibm.com: starting as the master for /master-analyzer-alert-server: skydivecicd1.sl.cloud9.ibm.com 2020-07-06T09:29:46.207+0300 INFO client/election.go:105 (*MasterElector).start skydivecicd1.sl.cloud9.ibm.com: starting as the master for /master-analyzer-topology-manager: skydivecicd1.sl.cloud9.ibm.com 2020-07-06T09:29:46.212+0300 INFO http/server.go:105 (*Server).Listen skydivecicd1.sl.cloud9.ibm.com: Listening on socket 0.0.0.0:64500 2020-07-06T09:29:46.212+0300 INFO hub/replication_endpoint.go:141 (*ReplicatorPeer).connect skydivecicd1.sl.cloud9.ibm.com: Connecting to peer: ws://127.0.0.1:64500/ws/replication 2020-07-06T09:29:46.212+0300 INFO analyzer/server.go:122 (*Server).createStartupCapture skydivecicd1.sl.cloud9.ibm.com: Invoke capturing of type '' from startup with gremlin: g.V().Has('Name','startup-vm2') and BPF: 2020-07-06T09:29:46.212+0300 INFO websocket/client.go:528 (*Client).Connect skydivecicd1.sl.cloud9.ibm.com: Connecting to ws://127.0.0.1:64500/ws/replication 2020-07-06T09:29:46.214+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Role links for: g 2020-07-06T09:29:46.214+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: admin < admin 2020-07-06T09:29:46.215+0300 DEBUG websocket/server.go:68 (*Server).serveMessages skydivecicd1.sl.cloud9.ibm.com: Enforcing websocket for /ws/replication, admin 2020-07-06T09:29:46.215+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, websocket, /ws/replication ---> true 2020-07-06T09:29:46.215+0300 DEBUG websocket/server.go:80 (*Server).serveMessages skydivecicd1.sl.cloud9.ibm.com: Serving messages for client skydivecicd1.sl.cloud9.ibm.com for pool /ws/replication type : [*websocket.Pool] 2020-07-06T09:29:46.216+0300 INFO websocket/server.go:114 (*Server).newIncomingClient skydivecicd1.sl.cloud9.ibm.com: New WebSocket Connection from 127.0.0.1:56618 : URI path /ws/replication 2020-07-06T09:29:46.216+0300 INFO websocket/client.go:552 (*Client).Connect skydivecicd1.sl.cloud9.ibm.com: Connected to ws://127.0.0.1:64500/ws/replication 2020-07-06T09:29:46.216+0300 DEBUG websocket/pool.go:122 (*incomerPool).AddClient skydivecicd1.sl.cloud9.ibm.com: AddClient skydivecicd1.sl.cloud9.ibm.com for pool /ws/replication type : [*websocket.Pool] 2020-07-06T09:29:46.216+0300 DEBUG hub/replication_endpoint.go:76 (*ReplicatorPeer).OnConnected skydivecicd1.sl.cloud9.ibm.com: Disconnecting from ws://127.0.0.1:64500/ws/replication since it's me 2020-07-06T09:29:46.216+0300 DEBUG hub/replication_endpoint.go:337 (*ReplicationEndpoint).OnConnected skydivecicd1.sl.cloud9.ibm.com: Disconnect skydivecicd1.sl.cloud9.ibm.com since it's me 2020-07-06T09:29:46.217+0300 DEBUG client/client.go:383 (*OnDemandClient).onAPIWatcherEvent skydivecicd1.sl.cloud9.ibm.com: New watcher event set for 6e5b02ad-4b8f-4e16-54e0-c2cd1b489e05 2020-07-06T09:29:46.217+0300 DEBUG websocket/pool.go:94 (*Pool).OnDisconnected skydivecicd1.sl.cloud9.ibm.com: OnDisconnected skydivecicd1.sl.cloud9.ibm.com for pool /ws/replication type : [*websocket.Pool] 2020-07-06T09:29:46.217+0300 DEBUG websocket/pool.go:148 (*Pool).RemoveClient skydivecicd1.sl.cloud9.ibm.com: Successfully removed client skydivecicd1.sl.cloud9.ibm.com for pool /ws/replication type : [*websocket.Pool] 2020-07-06T09:29:46.218+0300 DEBUG websocket/pool.go:109 (*Pool).AddClient skydivecicd1.sl.cloud9.ibm.com: AddClient skydivecicd1.sl.cloud9.ibm.com for pool HubClientPool type : [*websocket.Pool] 2020-07-06T09:29:46.219+0300 INFO plugin/topology.go:47 LoadTopologyPlugins skydivecicd1.sl.cloud9.ibm.com: Topology plugins: [] 2020-07-06T09:29:46.219+0300 INFO agent/topology_probes.go:148 NewTopologyProbeBundle skydivecicd1.sl.cloud9.ibm.com: Topology probes: [hardware netlink netns ovsdb blockdev docker lxd lldp runc socketinfo libvirt] 2020-07-06T09:29:46.220+0300 INFO ovsdb/ovs_of.go:176 NewOvsOfProbeHandler skydivecicd1.sl.cloud9.ibm.com: Adding OVS probe on /var/run/openvswitch/db.sock 2020-07-06T09:29:46.712+0300 INFO agent/flow_probes.go:42 NewFlowProbeBundle skydivecicd1.sl.cloud9.ibm.com: Flow probes: [pcapsocket ovssflow sflow gopacket dpdk ebpf ovsmirror ovsnetflow] 2020-07-06T09:29:46.712+0300 INFO agent/flow_probes.go:86 NewFlowProbeBundle skydivecicd1.sl.cloud9.ibm.com: Not compiled with dpdk support, skipping it 2020-07-06T09:29:46.713+0300 INFO http/server.go:105 (*Server).Listen skydivecicd1.sl.cloud9.ibm.com: Listening on socket 0.0.0.0:64499 2020-07-06T09:29:46.713+0300 INFO websocket/client.go:528 (*Client).Connect skydivecicd1.sl.cloud9.ibm.com: Connecting to ws://127.0.0.1:64500/ws/agent/topology 2020-07-06T09:29:46.715+0300 DEBUG websocket/server.go:68 (*Server).serveMessages skydivecicd1.sl.cloud9.ibm.com: Enforcing websocket for /ws/agent/topology, admin 2020-07-06T09:29:46.715+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, websocket, /ws/agent/topology ---> true 2020-07-06T09:29:46.715+0300 DEBUG websocket/server.go:80 (*Server).serveMessages skydivecicd1.sl.cloud9.ibm.com: Serving messages for client skydivecicd1.sl.cloud9.ibm.com for pool /ws/agent/topology type : [*websocket.Pool] 2020-07-06T09:29:46.715+0300 INFO websocket/server.go:114 (*Server).newIncomingClient skydivecicd1.sl.cloud9.ibm.com: New WebSocket Connection from 127.0.0.1:59750 : URI path /ws/agent/topology 2020-07-06T09:29:46.715+0300 INFO websocket/client.go:552 (*Client).Connect skydivecicd1.sl.cloud9.ibm.com: Connected to ws://127.0.0.1:64500/ws/agent/topology 2020-07-06T09:29:46.715+0300 INFO common/forwarder.go:56 (*Forwarder).OnNewMaster skydivecicd1.sl.cloud9.ibm.com: Using 127.0.0.1:64500 as master of topology forwarder 2020-07-06T09:29:46.716+0300 INFO common/forwarder.go:37 (*Forwarder).triggerResync skydivecicd1.sl.cloud9.ibm.com: Start a re-sync 2020-07-06T09:29:46.716+0300 DEBUG websocket/pool.go:122 (*incomerPool).AddClient skydivecicd1.sl.cloud9.ibm.com: AddClient skydivecicd1.sl.cloud9.ibm.com for pool /ws/agent/topology type : [*websocket.Pool] 2020-07-06T09:29:46.716+0300 DEBUG client/flow_client.go:80 (*FlowClientUDPConn).Connect skydivecicd1.sl.cloud9.ibm.com: UDP client dialup done for 127.0.0.1:64500 2020-07-06T09:29:46.717+0300 DEBUG common/publisher_endpoint.go:96 (*PublisherEndpoint).OnStructMessage skydivecicd1.sl.cloud9.ibm.com: Authoritative client registered agent.skydivecicd1.sl.cloud9.ibm.com 2020-07-06T09:29:46.717+0300 DEBUG common/publisher_endpoint.go:124 (*PublisherEndpoint).OnStructMessage skydivecicd1.sl.cloud9.ibm.com: Handling sync message from skydivecicd1.sl.cloud9.ibm.com 2020-07-06T09:29:46.724+0300 INFO ovsmirror/ovsmirror.go:418 (*ProbesHandler).cleanupOvsMirrors skydivecicd1.sl.cloud9.ibm.com: OvsMirror cleanup previous mirrors 2020-07-06T09:29:46.725+0300 INFO ovsdb/ovsdb.go:431 (*OvsMonitor).ovsUpdate skydivecicd1.sl.cloud9.ibm.com: OpenvSwitch system updated 2020-07-06T09:29:46.725+0300 DEBUG lxd/lxd.go:189 (*ProbeHandler).Do skydivecicd1.sl.cloud9.ibm.com: Connecting to LXD 2020-07-06T09:29:46.726+0300 DEBUG netns/netns.go:291 (*ProbeHandler).start skydivecicd1.sl.cloud9.ibm.com: ProbeHandler initialized 2020-07-06T09:29:46.726+0300 DEBUG netns/netns.go:285 (*ProbeHandler).initializeRunPath skydivecicd1.sl.cloud9.ibm.com: ProbeHandler initialized /var/run/netns 2020-07-06T09:29:46.727+0300 DEBUG netns/netns.go:133 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Register network namespace: /var/run/docker/netns/32121c372f06 2020-07-06T09:29:46.727+0300 DEBUG netns/netns.go:168 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Network namespace added: 3,4026532257 2020-07-06T09:29:46.738+0300 INFO ovsmirror/ovsmirror.go:418 (*ProbesHandler).cleanupOvsMirrors skydivecicd1.sl.cloud9.ibm.com: OvsMirror cleanup previous mirrors 2020-07-06T09:29:46.740+0300 INFO ovsdb/ovsdb.go:431 (*OvsMonitor).ovsUpdate skydivecicd1.sl.cloud9.ibm.com: OpenvSwitch system updated 2020-07-06T09:29:46.798+0300 DEBUG netns/netns.go:186 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Registering namespace: 3,4026532257 2020-07-06T09:29:46.798+0300 DEBUG runc/runc.go:362 (*ProbeHandler).initialize skydivecicd1.sl.cloud9.ibm.com: Probe initialized for /run/runc 2020-07-06T09:29:46.799+0300 DEBUG netns/netns.go:285 (*ProbeHandler).initializeRunPath skydivecicd1.sl.cloud9.ibm.com: ProbeHandler initialized /var/run/docker/netns 2020-07-06T09:29:46.799+0300 DEBUG netlink/netlink.go:1089 (*Probe).start skydivecicd1.sl.cloud9.ibm.com: Start polling netlink event for ded01144-3925-4ae5-6154-1c3c4a59641f 2020-07-06T09:29:46.799+0300 DEBUG netlink/netlink.go:836 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize Netlink interfaces for ded01144-3925-4ae5-6154-1c3c4a59641f 2020-07-06T09:29:46.799+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD lo(1,device) within ded01144-3925-4ae5-6154-1c3c4a59641f 2020-07-06T09:29:46.800+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (lo): operation not supported 2020-07-06T09:29:46.801+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD gre0(2,gre) within ded01144-3925-4ae5-6154-1c3c4a59641f 2020-07-06T09:29:46.801+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (gre0): operation not supported 2020-07-06T09:29:46.802+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD gretap0(3,gretap) within ded01144-3925-4ae5-6154-1c3c4a59641f 2020-07-06T09:29:46.802+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (gretap0): operation not supported 2020-07-06T09:29:46.803+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD erspan0(4,erspan) within ded01144-3925-4ae5-6154-1c3c4a59641f 2020-07-06T09:29:46.803+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (erspan0): operation not supported 2020-07-06T09:29:46.804+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD eth0(26041,veth) within ded01144-3925-4ae5-6154-1c3c4a59641f 2020-07-06T09:29:46.826+0300 DEBUG netlink/netlink.go:1089 (*Probe).start skydivecicd1.sl.cloud9.ibm.com: Start polling netlink event for b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:29:46.826+0300 DEBUG netlink/netlink.go:836 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize Netlink interfaces for b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:29:46.827+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD lo(1,device) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:29:46.828+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (lo): operation not supported 2020-07-06T09:29:46.829+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD eno1(2,device) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:29:46.831+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD eno2(3,device) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:29:46.833+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD eno3(4,device) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:29:46.834+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD eno4(5,device) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:29:46.836+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD eno5(6,device) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:29:46.837+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD eno6(7,device) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:29:46.839+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD tun99(8,tun) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:29:46.840+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD docker0(9,bridge) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:29:46.842+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD vboxnet0(15,device) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:29:46.844+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD virbr0-nic(18455,tun) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:29:46.846+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD gre0(25,gre) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:29:46.847+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (gre0): operation not supported 2020-07-06T09:29:46.847+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD gretap0(26,gretap) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:29:46.848+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (gretap0): operation not supported 2020-07-06T09:29:46.849+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD erspan0(27,erspan) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:29:46.850+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (erspan0): operation not supported 2020-07-06T09:29:46.851+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD lxdbr0(26039,bridge) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:29:46.854+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD veth06c105b(26042,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:29:47.554+0300 DEBUG lxd/lxd.go:224 (*ProbeHandler).Do.func2 skydivecicd1.sl.cloud9.ibm.com: Listing LXD containers 2020-07-06T09:29:47.560+0300 DEBUG docker/docker.go:184 (*ProbeHandler).Do skydivecicd1.sl.cloud9.ibm.com: Connecting to Docker daemon: unix:///var/run/docker.sock 2020-07-06T09:29:47.770+0300 INFO docker/docker.go:199 (*ProbeHandler).Do skydivecicd1.sl.cloud9.ibm.com: Connected to Docker 19.03.2 2020-07-06T09:29:47.836+0300 DEBUG docker/docker.go:87 (*ProbeHandler).registerContainer skydivecicd1.sl.cloud9.ibm.com: Register docker container 84963e9fdd4a5eb00239c3521a6352c47ec0d504db9295e08dbb8075f7fdc7b9 and PID 11846 2020-07-06T09:29:47.836+0300 DEBUG netns/netns.go:133 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Register network namespace: /proc/11846/ns/net 2020-07-06T09:29:47.836+0300 DEBUG netns/netns.go:164 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Increasing counter for namespace 3,4026532257 to 2 2020-07-06T09:29:50.562+0300 DEBUG tests/tests.go:325 execCmds skydivecicd1.sl.cloud9.ibm.com: Executing command [ip netns add alert-ns-webhook] 2020-07-06T09:29:50.701+0300 DEBUG netns/netns.go:133 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Register network namespace: /var/run/netns/alert-ns-webhook 2020-07-06T09:29:50.703+0300 DEBUG tests/tests.go:328 execCmds skydivecicd1.sl.cloud9.ibm.com: Command returned 2020-07-06T09:29:50.784+0300 DEBUG netns/netns.go:168 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Network namespace added: 3,4026532835 2020-07-06T09:29:50.786+0300 DEBUG netns/netns.go:186 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Registering namespace: 3,4026532835 2020-07-06T09:29:50.786+0300 DEBUG netlink/netlink.go:1089 (*Probe).start skydivecicd1.sl.cloud9.ibm.com: Start polling netlink event for d5c8950e-de26-48db-6533-c0657a32df98 2020-07-06T09:29:50.787+0300 DEBUG netlink/netlink.go:836 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize Netlink interfaces for d5c8950e-de26-48db-6533-c0657a32df98 2020-07-06T09:29:50.787+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD lo(1,device) within d5c8950e-de26-48db-6533-c0657a32df98 2020-07-06T09:29:50.788+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (lo): operation not supported 2020-07-06T09:29:50.791+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD gre0(2,gre) within d5c8950e-de26-48db-6533-c0657a32df98 2020-07-06T09:29:50.791+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (gre0): operation not supported 2020-07-06T09:29:50.793+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD gretap0(3,gretap) within d5c8950e-de26-48db-6533-c0657a32df98 2020-07-06T09:29:50.794+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (gretap0): operation not supported 2020-07-06T09:29:50.795+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD erspan0(4,erspan) within d5c8950e-de26-48db-6533-c0657a32df98 2020-07-06T09:29:50.795+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (erspan0): operation not supported 2020-07-06T09:29:51.901+0300 INFO client/election.go:105 (*MasterElector).start skydivecicd1.sl.cloud9.ibm.com: starting as the master for /master-analyzer-es-rolling-index:86c66954: skydivecicd1.sl.cloud9.ibm.com 2020-07-06T09:29:51.902+0300 INFO elasticsearch/client.go:235 (*Client).start skydivecicd1.sl.cloud9.ibm.com: client started for skydive_flow, skydive_metric, skydive_rawpacket 2020-07-06T09:29:52.339+0300 ERROR netlink/sriov.go:138 (*Probe).handleSriov skydivecicd1.sl.cloud9.ibm.com: SR-IOV: cannot get numvfs of PCI - All attempts fail: #1: zero VFS #2: zero VFS #3: zero VFS #4: zero VFS #5: zero VFS #6: zero VFS #7: zero VFS #8: zero VFS #9: zero VFS #10: zero VFS 2020-07-06T09:29:52.411+0300 ERROR netlink/sriov.go:138 (*Probe).handleSriov skydivecicd1.sl.cloud9.ibm.com: SR-IOV: cannot get numvfs of PCI - All attempts fail: #1: zero VFS #2: zero VFS #3: zero VFS #4: zero VFS #5: zero VFS #6: zero VFS #7: zero VFS #8: zero VFS #9: zero VFS #10: zero VFS 2020-07-06T09:29:52.438+0300 ERROR netlink/sriov.go:138 (*Probe).handleSriov skydivecicd1.sl.cloud9.ibm.com: SR-IOV: cannot get numvfs of PCI - All attempts fail: #1: zero VFS #2: zero VFS #3: zero VFS #4: zero VFS #5: zero VFS #6: zero VFS #7: zero VFS #8: zero VFS #9: zero VFS #10: zero VFS 2020-07-06T09:29:52.439+0300 ERROR netlink/sriov.go:138 (*Probe).handleSriov skydivecicd1.sl.cloud9.ibm.com: SR-IOV: cannot get numvfs of PCI - All attempts fail: #1: zero VFS #2: zero VFS #3: zero VFS #4: zero VFS #5: zero VFS #6: zero VFS #7: zero VFS #8: zero VFS #9: zero VFS #10: zero VFS 2020-07-06T09:29:52.440+0300 ERROR netlink/sriov.go:138 (*Probe).handleSriov skydivecicd1.sl.cloud9.ibm.com: SR-IOV: cannot get numvfs of PCI - All attempts fail: #1: zero VFS #2: zero VFS #3: zero VFS #4: zero VFS #5: zero VFS #6: zero VFS #7: zero VFS #8: zero VFS #9: zero VFS #10: zero VFS 2020-07-06T09:29:52.464+0300 ERROR netlink/sriov.go:138 (*Probe).handleSriov skydivecicd1.sl.cloud9.ibm.com: SR-IOV: cannot get numvfs of PCI - All attempts fail: #1: zero VFS #2: zero VFS #3: zero VFS #4: zero VFS #5: zero VFS #6: zero VFS #7: zero VFS #8: zero VFS #9: zero VFS #10: zero VFS 2020-07-06T09:29:52.711+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, alert, write ---> true 2020-07-06T09:29:52.716+0300 DEBUG alert/server.go:325 (*Server).registerAlert skydivecicd1.sl.cloud9.ibm.com: Registering new alert: &{Alert:0xc0008f0800 graph:0xc0005decc0 lastEval: kind:1 data:http://localhost:8080/ traversalSequence:0xc0008380c0 gremlinParser:0xc0005f55c0} 2020-07-06T09:29:55.158+0300 INFO alert/server.go:221 (*Server).triggerAlert skydivecicd1.sl.cloud9.ibm.com: Triggering alert e6d9d9d8-b79d-430c-6ed4-1bff6792947d of type http://localhost:8080/ 2020-07-06T09:29:55.159+0300 DEBUG alert/server.go:237 (*Server).triggerAlert skydivecicd1.sl.cloud9.ibm.com: Alert e6d9d9d8-b79d-430c-6ed4-1bff6792947d of type http://localhost:8080/ was triggerred 2020-07-06T09:29:55.722+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, alert, write ---> true 2020-07-06T09:29:55.725+0300 DEBUG alert/server.go:368 (*Server).unregisterAlert skydivecicd1.sl.cloud9.ibm.com: Unregistering alert: e6d9d9d8-b79d-430c-6ed4-1bff6792947d 2020-07-06T09:29:55.730+0300 DEBUG tests/tests.go:325 execCmds skydivecicd1.sl.cloud9.ibm.com: Executing command [ip netns del alert-ns-webhook] 2020-07-06T09:29:55.732+0300 DEBUG netns/netns.go:216 (*ProbeHandler).Unregister skydivecicd1.sl.cloud9.ibm.com: Unregister network Namespace: /var/run/netns/alert-ns-webhook 2020-07-06T09:29:55.732+0300 DEBUG tests/tests.go:328 execCmds skydivecicd1.sl.cloud9.ibm.com: Command returned --- PASS: TestAlertWebhook (14.28s) tests.go:479: Creating captures tests.go:495: Executing setup commands tests.go:512: Checking captures are correctly set up tests.go:577: Executing settle function tests.go:592: Executing setup function tests.go:726: Running checks tests.go:753: Running tear down commands tests.go:646: Removing existing injections tests.go:473: Removing existing captures 2020-07-06T09:29:55.732+0300 DEBUG netns/netns.go:240 (*ProbeHandler).Unregister skydivecicd1.sl.cloud9.ibm.com: Network namespace deleted: 3,4026532835 === RUN TestAlertScript 2020-07-06T09:29:55.733+0300 DEBUG tests/tests.go:325 execCmds skydivecicd1.sl.cloud9.ibm.com: Executing command [ip netns add alert-ns-script] 2020-07-06T09:29:55.736+0300 DEBUG netns/netns.go:133 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Register network namespace: /var/run/netns/alert-ns-script 2020-07-06T09:29:55.736+0300 DEBUG tests/tests.go:328 execCmds skydivecicd1.sl.cloud9.ibm.com: Command returned 2020-07-06T09:29:55.814+0300 DEBUG netns/netns.go:168 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Network namespace added: 3,4026532918 2020-07-06T09:29:55.815+0300 DEBUG netns/netns.go:186 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Registering namespace: 3,4026532918 2020-07-06T09:29:55.816+0300 DEBUG netlink/netlink.go:1089 (*Probe).start skydivecicd1.sl.cloud9.ibm.com: Start polling netlink event for f5666eae-6827-49cc-6b31-91a061ba7abe 2020-07-06T09:29:55.816+0300 DEBUG netlink/netlink.go:836 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize Netlink interfaces for f5666eae-6827-49cc-6b31-91a061ba7abe 2020-07-06T09:29:55.816+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD lo(1,device) within f5666eae-6827-49cc-6b31-91a061ba7abe 2020-07-06T09:29:55.816+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (lo): operation not supported 2020-07-06T09:29:55.818+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD gre0(2,gre) within f5666eae-6827-49cc-6b31-91a061ba7abe 2020-07-06T09:29:55.818+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (gre0): operation not supported 2020-07-06T09:29:55.820+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD gretap0(3,gretap) within f5666eae-6827-49cc-6b31-91a061ba7abe 2020-07-06T09:29:55.821+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (gretap0): operation not supported 2020-07-06T09:29:55.823+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD erspan0(4,erspan) within f5666eae-6827-49cc-6b31-91a061ba7abe 2020-07-06T09:29:55.823+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (erspan0): operation not supported 2020-07-06T09:29:57.738+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, alert, write ---> true 2020-07-06T09:29:57.742+0300 DEBUG alert/server.go:325 (*Server).registerAlert skydivecicd1.sl.cloud9.ibm.com: Registering new alert: &{Alert:0xc000eb9d80 graph:0xc0005decc0 lastEval: kind:2 data:/tmp/example691855408 traversalSequence:0xc0009a9840 gremlinParser:0xc0005f55c0} 2020-07-06T09:29:57.743+0300 INFO alert/server.go:221 (*Server).triggerAlert skydivecicd1.sl.cloud9.ibm.com: Triggering alert 49b80f55-b350-4f0f-743b-4e151f127399 of type file:///tmp/example691855408 2020-07-06T09:29:57.744+0300 DEBUG alert/server.go:237 (*Server).triggerAlert skydivecicd1.sl.cloud9.ibm.com: Alert 49b80f55-b350-4f0f-743b-4e151f127399 of type file:///tmp/example691855408 was triggerred 2020-07-06T09:29:57.744+0300 DEBUG alert/server.go:142 (*GremlinAlert).trigger skydivecicd1.sl.cloud9.ibm.com: Executing command '/tmp/example691855408' 2020-07-06T09:29:57.750+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, alert, write ---> true 2020-07-06T09:29:57.751+0300 DEBUG alert/server.go:368 (*Server).unregisterAlert skydivecicd1.sl.cloud9.ibm.com: Unregistering alert: 49b80f55-b350-4f0f-743b-4e151f127399 2020-07-06T09:29:57.754+0300 DEBUG tests/tests.go:325 execCmds skydivecicd1.sl.cloud9.ibm.com: Executing command [ip netns del alert-ns-script] 2020-07-06T09:29:57.755+0300 DEBUG netns/netns.go:216 (*ProbeHandler).Unregister skydivecicd1.sl.cloud9.ibm.com: Unregister network Namespace: /var/run/netns/alert-ns-script 2020-07-06T09:29:57.755+0300 DEBUG tests/tests.go:328 execCmds skydivecicd1.sl.cloud9.ibm.com: Command returned 2020-07-06T09:29:57.755+0300 DEBUG netns/netns.go:240 (*ProbeHandler).Unregister skydivecicd1.sl.cloud9.ibm.com: Network namespace deleted: 3,4026532918 --- PASS: TestAlertScript (2.02s) tests.go:479: Creating captures tests.go:495: Executing setup commands tests.go:512: Checking captures are correctly set up tests.go:577: Executing settle function tests.go:592: Executing setup function tests.go:726: Running checks tests.go:753: Running tear down commands tests.go:646: Removing existing injections tests.go:473: Removing existing captures === RUN TestAlertWithTimer 2020-07-06T09:29:57.756+0300 DEBUG tests/tests.go:325 execCmds skydivecicd1.sl.cloud9.ibm.com: Executing command [ip netns add alert-ns-timer] 2020-07-06T09:29:57.758+0300 DEBUG netns/netns.go:133 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Register network namespace: /var/run/netns/alert-ns-timer 2020-07-06T09:29:57.759+0300 DEBUG tests/tests.go:328 execCmds skydivecicd1.sl.cloud9.ibm.com: Command returned 2020-07-06T09:29:57.841+0300 DEBUG netns/netns.go:168 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Network namespace added: 3,4026532835 2020-07-06T09:29:57.843+0300 DEBUG netns/netns.go:186 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Registering namespace: 3,4026532835 2020-07-06T09:29:57.844+0300 DEBUG netlink/netlink.go:1089 (*Probe).start skydivecicd1.sl.cloud9.ibm.com: Start polling netlink event for cf2e8520-2b27-4ca4-4824-1eeb5ab23307 2020-07-06T09:29:57.844+0300 DEBUG netlink/netlink.go:836 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize Netlink interfaces for cf2e8520-2b27-4ca4-4824-1eeb5ab23307 2020-07-06T09:29:57.845+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD lo(1,device) within cf2e8520-2b27-4ca4-4824-1eeb5ab23307 2020-07-06T09:29:57.845+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (lo): operation not supported 2020-07-06T09:29:57.848+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD gre0(2,gre) within cf2e8520-2b27-4ca4-4824-1eeb5ab23307 2020-07-06T09:29:57.849+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (gre0): operation not supported 2020-07-06T09:29:57.851+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD gretap0(3,gretap) within cf2e8520-2b27-4ca4-4824-1eeb5ab23307 2020-07-06T09:29:57.851+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (gretap0): operation not supported 2020-07-06T09:29:57.852+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD erspan0(4,erspan) within cf2e8520-2b27-4ca4-4824-1eeb5ab23307 2020-07-06T09:29:57.852+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (erspan0): operation not supported 2020-07-06T09:29:59.761+0300 DEBUG websocket/server.go:68 (*Server).serveMessages skydivecicd1.sl.cloud9.ibm.com: Enforcing websocket for /ws/subscriber, admin 2020-07-06T09:29:59.762+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, websocket, /ws/subscriber ---> true 2020-07-06T09:29:59.762+0300 DEBUG websocket/server.go:80 (*Server).serveMessages skydivecicd1.sl.cloud9.ibm.com: Serving messages for client 127.0.0.1:59768 for pool /ws/subscriber type : [*websocket.Pool] 2020-07-06T09:29:59.762+0300 INFO websocket/server.go:114 (*Server).newIncomingClient skydivecicd1.sl.cloud9.ibm.com: New WebSocket Connection from 127.0.0.1:59768 : URI path /ws/subscriber 2020-07-06T09:29:59.763+0300 DEBUG websocket/pool.go:122 (*incomerPool).AddClient skydivecicd1.sl.cloud9.ibm.com: AddClient 127.0.0.1:59768 for pool /ws/subscriber type : [*websocket.Pool] 2020-07-06T09:29:59.764+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, alert, write ---> true 2020-07-06T09:29:59.767+0300 DEBUG alert/server.go:325 (*Server).registerAlert skydivecicd1.sl.cloud9.ibm.com: Registering new alert: &{Alert:0xc000c44e00 graph:0xc0005decc0 lastEval: kind:0 data: traversalSequence:0xc000ac4740 gremlinParser:0xc0005f55c0} 2020-07-06T09:29:59.767+0300 INFO alert/server.go:221 (*Server).triggerAlert skydivecicd1.sl.cloud9.ibm.com: Triggering alert 7e89a3c9-5a8c-438c-5612-d80bbefd0747 of type 2020-07-06T09:29:59.768+0300 DEBUG alert/server.go:237 (*Server).triggerAlert skydivecicd1.sl.cloud9.ibm.com: Alert 7e89a3c9-5a8c-438c-5612-d80bbefd0747 of type was triggerred 2020-07-06T09:29:59.773+0300 DEBUG websocket/pool.go:94 (*Pool).OnDisconnected skydivecicd1.sl.cloud9.ibm.com: OnDisconnected 127.0.0.1:59768 for pool /ws/subscriber type : [*websocket.Pool] 2020-07-06T09:29:59.773+0300 DEBUG websocket/pool.go:148 (*Pool).RemoveClient skydivecicd1.sl.cloud9.ibm.com: Successfully removed client 127.0.0.1:59768 for pool /ws/subscriber type : [*websocket.Pool] 2020-07-06T09:29:59.775+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, alert, write ---> true 2020-07-06T09:29:59.776+0300 DEBUG alert/server.go:368 (*Server).unregisterAlert skydivecicd1.sl.cloud9.ibm.com: Unregistering alert: 7e89a3c9-5a8c-438c-5612-d80bbefd0747 2020-07-06T09:29:59.781+0300 DEBUG tests/tests.go:325 execCmds skydivecicd1.sl.cloud9.ibm.com: Executing command [ip netns del alert-ns-timer] 2020-07-06T09:29:59.782+0300 DEBUG netns/netns.go:216 (*ProbeHandler).Unregister skydivecicd1.sl.cloud9.ibm.com: Unregister network Namespace: /var/run/netns/alert-ns-timer 2020-07-06T09:29:59.783+0300 DEBUG tests/tests.go:328 execCmds skydivecicd1.sl.cloud9.ibm.com: Command returned 2020-07-06T09:29:59.783+0300 DEBUG netns/netns.go:240 (*ProbeHandler).Unregister skydivecicd1.sl.cloud9.ibm.com: Network namespace deleted: 3,4026532835 --- PASS: TestAlertWithTimer (2.03s) tests.go:479: Creating captures tests.go:495: Executing setup commands tests.go:512: Checking captures are correctly set up tests.go:577: Executing settle function tests.go:592: Executing setup function tests.go:726: Running checks tests.go:753: Running tear down commands tests.go:646: Removing existing injections tests.go:473: Removing existing captures === RUN TestMultipleTriggering 2020-07-06T09:29:59.784+0300 DEBUG tests/tests.go:325 execCmds skydivecicd1.sl.cloud9.ibm.com: Executing command [ip netns add alert-lo-down] 2020-07-06T09:29:59.787+0300 DEBUG netns/netns.go:133 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Register network namespace: /var/run/netns/alert-lo-down 2020-07-06T09:29:59.788+0300 DEBUG tests/tests.go:328 execCmds skydivecicd1.sl.cloud9.ibm.com: Command returned 2020-07-06T09:29:59.809+0300 DEBUG netns/netns.go:168 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Network namespace added: 3,4026532999 2020-07-06T09:29:59.809+0300 DEBUG netns/netns.go:186 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Registering namespace: 3,4026532999 2020-07-06T09:29:59.810+0300 DEBUG netlink/netlink.go:1089 (*Probe).start skydivecicd1.sl.cloud9.ibm.com: Start polling netlink event for 5bf50aae-826a-46b2-5cc9-c72c113bbf51 2020-07-06T09:29:59.810+0300 DEBUG netlink/netlink.go:836 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize Netlink interfaces for 5bf50aae-826a-46b2-5cc9-c72c113bbf51 2020-07-06T09:29:59.810+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD lo(1,device) within 5bf50aae-826a-46b2-5cc9-c72c113bbf51 2020-07-06T09:29:59.811+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (lo): operation not supported 2020-07-06T09:29:59.812+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD gre0(2,gre) within 5bf50aae-826a-46b2-5cc9-c72c113bbf51 2020-07-06T09:29:59.813+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (gre0): operation not supported 2020-07-06T09:29:59.815+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD gretap0(3,gretap) within 5bf50aae-826a-46b2-5cc9-c72c113bbf51 2020-07-06T09:29:59.816+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (gretap0): operation not supported 2020-07-06T09:29:59.818+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD erspan0(4,erspan) within 5bf50aae-826a-46b2-5cc9-c72c113bbf51 2020-07-06T09:29:59.818+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (erspan0): operation not supported 2020-07-06T09:30:01.790+0300 DEBUG websocket/server.go:68 (*Server).serveMessages skydivecicd1.sl.cloud9.ibm.com: Enforcing websocket for /ws/subscriber, admin 2020-07-06T09:30:01.791+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, websocket, /ws/subscriber ---> true 2020-07-06T09:30:01.791+0300 DEBUG websocket/server.go:80 (*Server).serveMessages skydivecicd1.sl.cloud9.ibm.com: Serving messages for client 127.0.0.1:59770 for pool /ws/subscriber type : [*websocket.Pool] 2020-07-06T09:30:01.792+0300 INFO websocket/server.go:114 (*Server).newIncomingClient skydivecicd1.sl.cloud9.ibm.com: New WebSocket Connection from 127.0.0.1:59770 : URI path /ws/subscriber 2020-07-06T09:30:01.792+0300 DEBUG websocket/pool.go:122 (*incomerPool).AddClient skydivecicd1.sl.cloud9.ibm.com: AddClient 127.0.0.1:59770 for pool /ws/subscriber type : [*websocket.Pool] 2020-07-06T09:30:01.795+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, alert, write ---> true 2020-07-06T09:30:01.799+0300 DEBUG alert/server.go:325 (*Server).registerAlert skydivecicd1.sl.cloud9.ibm.com: Registering new alert: &{Alert:0xc000e96080 graph:0xc0005decc0 lastEval: kind:0 data: traversalSequence:0xc0009a80c0 gremlinParser:0xc0005f55c0} 2020-07-06T09:30:01.800+0300 INFO alert/server.go:221 (*Server).triggerAlert skydivecicd1.sl.cloud9.ibm.com: Triggering alert 99c31992-f561-45c7-6840-1c5d7eba1a0a of type 2020-07-06T09:30:01.800+0300 DEBUG alert/server.go:237 (*Server).triggerAlert skydivecicd1.sl.cloud9.ibm.com: Alert 99c31992-f561-45c7-6840-1c5d7eba1a0a of type was triggerred 2020-07-06T09:30:01.806+0300 DEBUG tests/tests.go:325 execCmds skydivecicd1.sl.cloud9.ibm.com: Executing command [ip netns exec alert-lo-down ip l set lo up] 2020-07-06T09:30:01.808+0300 INFO alert/server.go:221 (*Server).triggerAlert skydivecicd1.sl.cloud9.ibm.com: Triggering alert 99c31992-f561-45c7-6840-1c5d7eba1a0a of type 2020-07-06T09:30:01.809+0300 DEBUG alert/server.go:237 (*Server).triggerAlert skydivecicd1.sl.cloud9.ibm.com: Alert 99c31992-f561-45c7-6840-1c5d7eba1a0a of type was triggerred 2020-07-06T09:30:01.826+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for lo(1,device) within 5bf50aae-826a-46b2-5cc9-c72c113bbf51 2020-07-06T09:30:01.827+0300 DEBUG tests/tests.go:328 execCmds skydivecicd1.sl.cloud9.ibm.com: Command returned 2020-07-06T09:30:01.827+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (lo): operation not supported 2020-07-06T09:30:01.828+0300 DEBUG tests/tests.go:325 execCmds skydivecicd1.sl.cloud9.ibm.com: Executing command [ip netns exec alert-lo-down ip l set lo down] 2020-07-06T09:30:01.831+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for lo(1,device) within 5bf50aae-826a-46b2-5cc9-c72c113bbf51 2020-07-06T09:30:01.831+0300 INFO alert/server.go:221 (*Server).triggerAlert skydivecicd1.sl.cloud9.ibm.com: Triggering alert 99c31992-f561-45c7-6840-1c5d7eba1a0a of type 2020-07-06T09:30:01.831+0300 DEBUG tests/tests.go:328 execCmds skydivecicd1.sl.cloud9.ibm.com: Command returned 2020-07-06T09:30:01.831+0300 DEBUG alert/server.go:237 (*Server).triggerAlert skydivecicd1.sl.cloud9.ibm.com: Alert 99c31992-f561-45c7-6840-1c5d7eba1a0a of type was triggerred 2020-07-06T09:30:01.831+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (lo): operation not supported 2020-07-06T09:30:01.832+0300 DEBUG websocket/pool.go:94 (*Pool).OnDisconnected skydivecicd1.sl.cloud9.ibm.com: OnDisconnected 127.0.0.1:59770 for pool /ws/subscriber type : [*websocket.Pool] 2020-07-06T09:30:01.832+0300 DEBUG websocket/pool.go:148 (*Pool).RemoveClient skydivecicd1.sl.cloud9.ibm.com: Successfully removed client 127.0.0.1:59770 for pool /ws/subscriber type : [*websocket.Pool] 2020-07-06T09:30:01.833+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, alert, write ---> true 2020-07-06T09:30:01.836+0300 DEBUG alert/server.go:368 (*Server).unregisterAlert skydivecicd1.sl.cloud9.ibm.com: Unregistering alert: 99c31992-f561-45c7-6840-1c5d7eba1a0a 2020-07-06T09:30:01.840+0300 DEBUG tests/tests.go:325 execCmds skydivecicd1.sl.cloud9.ibm.com: Executing command [ip netns del alert-lo-down] 2020-07-06T09:30:01.842+0300 DEBUG netns/netns.go:216 (*ProbeHandler).Unregister skydivecicd1.sl.cloud9.ibm.com: Unregister network Namespace: /var/run/netns/alert-lo-down 2020-07-06T09:30:01.842+0300 DEBUG tests/tests.go:328 execCmds skydivecicd1.sl.cloud9.ibm.com: Command returned 2020-07-06T09:30:01.842+0300 DEBUG netns/netns.go:240 (*ProbeHandler).Unregister skydivecicd1.sl.cloud9.ibm.com: Network namespace deleted: 3,4026532999 --- PASS: TestMultipleTriggering (2.06s) tests.go:479: Creating captures tests.go:495: Executing setup commands tests.go:512: Checking captures are correctly set up tests.go:577: Executing settle function tests.go:592: Executing setup function alert_test.go:403: alert created with UUID : 99c31992-f561-45c7-6840-1c5d7eba1a0a tests.go:726: Running checks alert_test.go:447: ws msg received with namespace Alert and alertMsg UUID 99c31992-f561-45c7-6840-1c5d7eba1a0a alert_test.go:447: ws msg received with namespace Alert and alertMsg UUID 99c31992-f561-45c7-6840-1c5d7eba1a0a tests.go:753: Running tear down commands tests.go:646: Removing existing injections tests.go:473: Removing existing captures === RUN TestAlertAPI 2020-07-06T09:30:01.844+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, alert, write ---> true 2020-07-06T09:30:01.848+0300 DEBUG alert/server.go:325 (*Server).registerAlert skydivecicd1.sl.cloud9.ibm.com: Registering new alert: &{Alert:0xc001110300 graph:0xc0005decc0 lastEval: kind:0 data: traversalSequence:0xc000430280 gremlinParser:0xc0005f55c0} 2020-07-06T09:30:01.848+0300 INFO alert/server.go:221 (*Server).triggerAlert skydivecicd1.sl.cloud9.ibm.com: Triggering alert 60893262-5371-4656-486a-880e834b7ad0 of type 2020-07-06T09:30:01.851+0300 DEBUG alert/server.go:237 (*Server).triggerAlert skydivecicd1.sl.cloud9.ibm.com: Alert 60893262-5371-4656-486a-880e834b7ad0 of type was triggerred 2020-07-06T09:30:01.853+0300 INFO alert/server.go:221 (*Server).triggerAlert skydivecicd1.sl.cloud9.ibm.com: Triggering alert 60893262-5371-4656-486a-880e834b7ad0 of type 2020-07-06T09:30:01.854+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, alert, read ---> true 2020-07-06T09:30:01.854+0300 DEBUG alert/server.go:237 (*Server).triggerAlert skydivecicd1.sl.cloud9.ibm.com: Alert 60893262-5371-4656-486a-880e834b7ad0 of type was triggerred 2020-07-06T09:30:01.860+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, alert, read ---> true 2020-07-06T09:30:01.869+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, alert, write ---> true 2020-07-06T09:30:01.870+0300 DEBUG alert/server.go:368 (*Server).unregisterAlert skydivecicd1.sl.cloud9.ibm.com: Unregistering alert: 60893262-5371-4656-486a-880e834b7ad0 2020-07-06T09:30:01.875+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, alert, read ---> true --- PASS: TestAlertAPI (0.04s) === RUN TestCaptureAPI 2020-07-06T09:30:01.882+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, capture, read ---> true 2020-07-06T09:30:01.889+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, capture, write ---> true 2020-07-06T09:30:01.892+0300 DEBUG client/client.go:383 (*OnDemandClient).onAPIWatcherEvent skydivecicd1.sl.cloud9.ibm.com: New watcher event set for 9ffc57ad-dc1a-40ae-479f-c5136f1791c2 2020-07-06T09:30:01.896+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, capture, read ---> true 2020-07-06T09:30:01.902+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, capture, read ---> true 2020-07-06T09:30:01.913+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, capture, write ---> true 2020-07-06T09:30:01.914+0300 DEBUG client/client.go:383 (*OnDemandClient).onAPIWatcherEvent skydivecicd1.sl.cloud9.ibm.com: New watcher event delete for 9ffc57ad-dc1a-40ae-479f-c5136f1791c2 2020-07-06T09:30:01.918+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, capture, read ---> true 2020-07-06T09:30:01.924+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, capture, read ---> true --- PASS: TestCaptureAPI (0.05s) === RUN TestBlockDevSimple 2020-07-06T09:30:03.932+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, topology, read ---> true 2020-07-06T09:30:03.956+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, topology, read ---> true --- PASS: TestBlockDevSimple (2.18s) tests.go:479: Creating captures tests.go:495: Executing setup commands tests.go:512: Checking captures are correctly set up tests.go:577: Executing settle function tests.go:592: Executing setup function tests.go:726: Running checks tests.go:753: Running tear down commands tests.go:771: Replaying test with time 2020-07-06 09:30:03.955082794 +0300 IDT m=+22.637418122 (Unix: 1594017003), startTime 2020-07-06 09:30:03.929160526 +0300 IDT m=+22.611495880 (Unix: 1594017003) tests.go:646: Removing existing injections tests.go:473: Removing existing captures === RUN TestBlockDevWithJSON 2020-07-06T09:30:06.114+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, topology, read ---> true 2020-07-06T09:30:06.125+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, topology, read ---> true 2020-07-06T09:30:06.134+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, topology, read ---> true 2020-07-06T09:30:06.146+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, topology, read ---> true 2020-07-06T09:30:06.164+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, topology, read ---> true 2020-07-06T09:30:06.988+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, topology, read ---> true --- PASS: TestBlockDevWithJSON (3.26s) tests.go:479: Creating captures tests.go:495: Executing setup commands tests.go:512: Checking captures are correctly set up tests.go:577: Executing settle function tests.go:592: Executing setup function tests.go:726: Running checks tests.go:753: Running tear down commands tests.go:771: Replaying test with time 2020-07-06 09:30:06.14524987 +0300 IDT m=+24.827585206 (Unix: 1594017006), startTime 2020-07-06 09:30:06.109984051 +0300 IDT m=+24.792319427 (Unix: 1594017006) tests.go:646: Removing existing injections tests.go:473: Removing existing captures === RUN TestDockerSimple 2020-07-06T09:30:07.370+0300 DEBUG tests/tests.go:325 execCmds skydivecicd1.sl.cloud9.ibm.com: Executing command [docker run -d -t -i --name test-skydive-docker-simple busybox] 2020-07-06T09:30:12.748+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for veth4f776f3(26045,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:12.753+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for vethab1bfa9(26046,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:12.756+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for vethab1bfa9(26046,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:12.758+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for vethab1bfa9(26046,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:12.760+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for vethab1bfa9(26046,device) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:12.761+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for vethab1bfa9(26046,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:12.763+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for vethab1bfa9(26046,device) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:13.177+0300 DEBUG netns/netns.go:133 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Register network namespace: /var/run/docker/netns/3637dadb7eb0 2020-07-06T09:30:13.177+0300 DEBUG netns/netns.go:168 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Network namespace added: 3,4026532841 2020-07-06T09:30:13.178+0300 DEBUG netns/netns.go:186 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Registering namespace: 3,4026532841 2020-07-06T09:30:13.179+0300 DEBUG netlink/netlink.go:1089 (*Probe).start skydivecicd1.sl.cloud9.ibm.com: Start polling netlink event for b3538c94-eec4-488a-75e4-0ec546062707 2020-07-06T09:30:13.179+0300 DEBUG netlink/netlink.go:836 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize Netlink interfaces for b3538c94-eec4-488a-75e4-0ec546062707 2020-07-06T09:30:13.179+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD lo(1,device) within b3538c94-eec4-488a-75e4-0ec546062707 2020-07-06T09:30:13.180+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (lo): operation not supported 2020-07-06T09:30:13.181+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD gre0(2,gre) within b3538c94-eec4-488a-75e4-0ec546062707 2020-07-06T09:30:13.181+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (gre0): operation not supported 2020-07-06T09:30:13.183+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD gretap0(3,gretap) within b3538c94-eec4-488a-75e4-0ec546062707 2020-07-06T09:30:13.183+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (gretap0): operation not supported 2020-07-06T09:30:13.184+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD erspan0(4,erspan) within b3538c94-eec4-488a-75e4-0ec546062707 2020-07-06T09:30:13.184+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (erspan0): operation not supported 2020-07-06T09:30:13.228+0300 DEBUG netlink/netlink.go:1145 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink DEL event for veth4f776f3(26045) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:13.230+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for veth4f776f3(26045,veth) within b3538c94-eec4-488a-75e4-0ec546062707 2020-07-06T09:30:13.257+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for eth0(26045,veth) within b3538c94-eec4-488a-75e4-0ec546062707 2020-07-06T09:30:13.260+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for eth0(26045,veth) within b3538c94-eec4-488a-75e4-0ec546062707 2020-07-06T09:30:13.262+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for vethab1bfa9(26046,device) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:13.264+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for vethab1bfa9(26046,device) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:13.266+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for eth0(26045,veth) within b3538c94-eec4-488a-75e4-0ec546062707 2020-07-06T09:30:13.267+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for vethab1bfa9(26046,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:13.270+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for eth0(26045,veth) within b3538c94-eec4-488a-75e4-0ec546062707 2020-07-06T09:30:13.504+0300 DEBUG tests/tests.go:328 execCmds skydivecicd1.sl.cloud9.ibm.com: Command returned Unable to find image 'busybox:latest' locally latest: Pulling from library/busybox 91f30d776fb2: Pulling fs layer 91f30d776fb2: Verifying Checksum 91f30d776fb2: Download complete 91f30d776fb2: Pull complete Digest: sha256:9ddee63a712cea977267342e8750ecbc60d3aab25f04ceacfa795e6fce341793 Status: Downloaded newer image for busybox:latest b3d2cb0d3cbb792c7a6e00b8bb473039e07926d9eeb9f214337287eaa29c239f 2020-07-06T09:30:13.505+0300 DEBUG docker/docker.go:87 (*ProbeHandler).registerContainer skydivecicd1.sl.cloud9.ibm.com: Register docker container b3d2cb0d3cbb792c7a6e00b8bb473039e07926d9eeb9f214337287eaa29c239f and PID 19194 2020-07-06T09:30:13.505+0300 DEBUG netns/netns.go:133 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Register network namespace: /proc/19194/ns/net 2020-07-06T09:30:13.506+0300 DEBUG netns/netns.go:164 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Increasing counter for namespace 3,4026532841 to 2 2020-07-06T09:30:15.508+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, topology, read ---> true 2020-07-06T09:30:15.517+0300 DEBUG tests/tests.go:325 execCmds skydivecicd1.sl.cloud9.ibm.com: Executing command [docker rm -f test-skydive-docker-simple] 2020-07-06T09:30:15.874+0300 DEBUG docker/docker.go:165 (*ProbeHandler).unregisterContainer skydivecicd1.sl.cloud9.ibm.com: Stop listening for namespace /proc/19194/ns/net with PID 19194 2020-07-06T09:30:15.874+0300 DEBUG netns/netns.go:216 (*ProbeHandler).Unregister skydivecicd1.sl.cloud9.ibm.com: Unregister network Namespace: /proc/19194/ns/net 2020-07-06T09:30:15.874+0300 DEBUG netns/netns.go:235 (*ProbeHandler).Unregister skydivecicd1.sl.cloud9.ibm.com: Decremented counter for namespace 3,4026532841 to 1 2020-07-06T09:30:15.896+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for eth0(26045,veth) within b3538c94-eec4-488a-75e4-0ec546062707 2020-07-06T09:30:15.931+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for veth4f776f3(26045,veth) within b3538c94-eec4-488a-75e4-0ec546062707 2020-07-06T09:30:15.931+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for vethab1bfa9(26046,device) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:15.934+0300 WARN netlink/netlink.go:1164 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Failed to get Routes: Link not found 2020-07-06T09:30:15.934+0300 DEBUG netlink/netlink.go:1145 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink DEL event for veth4f776f3(26045) within b3538c94-eec4-488a-75e4-0ec546062707 2020-07-06T09:30:15.935+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for vethab1bfa9(26046,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:15.937+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for veth4f776f3(26045,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:15.971+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for vethab1bfa9(26046,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:15.990+0300 WARN netlink/netlink.go:1164 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Failed to get Routes: Link not found 2020-07-06T09:30:15.990+0300 WARN netlink/netlink.go:1164 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Failed to get Routes: Link not found 2020-07-06T09:30:15.991+0300 WARN netlink/netlink.go:1164 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Failed to get Routes: Link not found 2020-07-06T09:30:15.991+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for vethab1bfa9(26046,device) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:15.991+0300 DEBUG netlink/netlink.go:1145 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink DEL event for veth4f776f3(26045) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:15.993+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for vethab1bfa9(26046,device) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:15.993+0300 DEBUG netlink/netlink.go:1145 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink DEL event for vethab1bfa9(26046) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:15.995+0300 DEBUG netlink/netlink.go:1145 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink DEL event for vethab1bfa9(26046) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:16.600+0300 DEBUG tests/tests.go:328 execCmds skydivecicd1.sl.cloud9.ibm.com: Command returned test-skydive-docker-simple 2020-07-06T09:30:16.602+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, topology, read ---> true 2020-07-06T09:30:17.717+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, topology, read ---> true 2020-07-06T09:30:18.821+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, topology, read ---> true 2020-07-06T09:30:19.966+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, topology, read ---> true --- PASS: TestDockerSimple (12.79s) tests.go:479: Creating captures tests.go:495: Executing setup commands tests.go:512: Checking captures are correctly set up tests.go:577: Executing settle function tests.go:592: Executing setup function tests.go:726: Running checks tests.go:753: Running tear down commands tests.go:771: Replaying test with time 2020-07-06 09:30:15.517622638 +0300 IDT m=+34.199957961 (Unix: 1594017015), startTime 2020-07-06 09:30:15.505376739 +0300 IDT m=+34.187712112 (Unix: 1594017015) tests.go:646: Removing existing injections tests.go:473: Removing existing captures === RUN TestDockerShareNamespace 2020-07-06T09:30:20.157+0300 DEBUG tests/tests.go:325 execCmds skydivecicd1.sl.cloud9.ibm.com: Executing command [docker run -d -t -i --name test-skydive-docker-share-ns busybox] 2020-07-06T09:30:20.629+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for veth1540e49(26047,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:20.634+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for vethe9bd230(26048,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:20.636+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for vethe9bd230(26048,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:20.638+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for vethe9bd230(26048,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:20.640+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for vethe9bd230(26048,device) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:20.642+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for vethe9bd230(26048,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:20.646+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for vethe9bd230(26048,device) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:20.962+0300 DEBUG netns/netns.go:133 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Register network namespace: /var/run/docker/netns/a8ff0ce99b3c 2020-07-06T09:30:20.962+0300 DEBUG netns/netns.go:168 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Network namespace added: 3,4026533005 2020-07-06T09:30:20.963+0300 DEBUG netns/netns.go:186 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Registering namespace: 3,4026533005 2020-07-06T09:30:20.963+0300 DEBUG netlink/netlink.go:1089 (*Probe).start skydivecicd1.sl.cloud9.ibm.com: Start polling netlink event for f7523f74-b6ed-4f6b-4337-bcc85c22057f 2020-07-06T09:30:20.963+0300 DEBUG netlink/netlink.go:836 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize Netlink interfaces for f7523f74-b6ed-4f6b-4337-bcc85c22057f 2020-07-06T09:30:20.964+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD lo(1,device) within f7523f74-b6ed-4f6b-4337-bcc85c22057f 2020-07-06T09:30:20.964+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (lo): operation not supported 2020-07-06T09:30:20.966+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD gre0(2,gre) within f7523f74-b6ed-4f6b-4337-bcc85c22057f 2020-07-06T09:30:20.967+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (gre0): operation not supported 2020-07-06T09:30:20.968+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD gretap0(3,gretap) within f7523f74-b6ed-4f6b-4337-bcc85c22057f 2020-07-06T09:30:20.969+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (gretap0): operation not supported 2020-07-06T09:30:20.971+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD erspan0(4,erspan) within f7523f74-b6ed-4f6b-4337-bcc85c22057f 2020-07-06T09:30:20.971+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (erspan0): operation not supported 2020-07-06T09:30:21.014+0300 DEBUG netlink/netlink.go:1145 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink DEL event for veth1540e49(26047) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:21.015+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for veth1540e49(26047,veth) within f7523f74-b6ed-4f6b-4337-bcc85c22057f 2020-07-06T09:30:21.040+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for eth0(26047,veth) within f7523f74-b6ed-4f6b-4337-bcc85c22057f 2020-07-06T09:30:21.042+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for eth0(26047,veth) within f7523f74-b6ed-4f6b-4337-bcc85c22057f 2020-07-06T09:30:21.044+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for vethe9bd230(26048,device) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:21.047+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for vethe9bd230(26048,device) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:21.048+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for eth0(26047,veth) within f7523f74-b6ed-4f6b-4337-bcc85c22057f 2020-07-06T09:30:21.049+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for vethe9bd230(26048,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:21.053+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for eth0(26047,veth) within f7523f74-b6ed-4f6b-4337-bcc85c22057f 2020-07-06T09:30:21.289+0300 DEBUG tests/tests.go:328 execCmds skydivecicd1.sl.cloud9.ibm.com: Command returned e9c5612e47380c4ead5018e78ad3efce9b265c2175c7562407150471e5965ca9 2020-07-06T09:30:21.289+0300 DEBUG tests/tests.go:325 execCmds skydivecicd1.sl.cloud9.ibm.com: Executing command [docker run -d -t -i --name test-skydive-docker-share-ns2 --net=container:test-skydive-docker-share-ns busybox] 2020-07-06T09:30:21.290+0300 DEBUG docker/docker.go:87 (*ProbeHandler).registerContainer skydivecicd1.sl.cloud9.ibm.com: Register docker container e9c5612e47380c4ead5018e78ad3efce9b265c2175c7562407150471e5965ca9 and PID 19368 2020-07-06T09:30:21.290+0300 DEBUG netns/netns.go:133 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Register network namespace: /proc/19368/ns/net 2020-07-06T09:30:21.290+0300 DEBUG netns/netns.go:164 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Increasing counter for namespace 3,4026533005 to 2 2020-07-06T09:30:22.105+0300 DEBUG tests/tests.go:328 execCmds skydivecicd1.sl.cloud9.ibm.com: Command returned c0a597b77858fae6fe0c9d06635d0297159bd1cec0715b01f7cbee9a0ca89890 2020-07-06T09:30:22.107+0300 DEBUG docker/docker.go:87 (*ProbeHandler).registerContainer skydivecicd1.sl.cloud9.ibm.com: Register docker container c0a597b77858fae6fe0c9d06635d0297159bd1cec0715b01f7cbee9a0ca89890 and PID 19447 2020-07-06T09:30:22.107+0300 DEBUG netns/netns.go:133 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Register network namespace: /proc/19447/ns/net 2020-07-06T09:30:22.107+0300 DEBUG netns/netns.go:164 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Increasing counter for namespace 3,4026533005 to 3 2020-07-06T09:30:24.107+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, topology, read ---> true 2020-07-06T09:30:24.116+0300 DEBUG tests/tests.go:325 execCmds skydivecicd1.sl.cloud9.ibm.com: Executing command [docker rm -f test-skydive-docker-share-ns] 2020-07-06T09:30:24.323+0300 DEBUG docker/docker.go:165 (*ProbeHandler).unregisterContainer skydivecicd1.sl.cloud9.ibm.com: Stop listening for namespace /proc/19368/ns/net with PID 19368 2020-07-06T09:30:24.323+0300 DEBUG netns/netns.go:216 (*ProbeHandler).Unregister skydivecicd1.sl.cloud9.ibm.com: Unregister network Namespace: /proc/19368/ns/net 2020-07-06T09:30:24.323+0300 DEBUG netns/netns.go:235 (*ProbeHandler).Unregister skydivecicd1.sl.cloud9.ibm.com: Decremented counter for namespace 3,4026533005 to 2 2020-07-06T09:30:24.353+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for eth0(26047,veth) within f7523f74-b6ed-4f6b-4337-bcc85c22057f 2020-07-06T09:30:24.387+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for veth1540e49(26047,veth) within f7523f74-b6ed-4f6b-4337-bcc85c22057f 2020-07-06T09:30:24.387+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for vethe9bd230(26048,device) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:24.390+0300 WARN netlink/netlink.go:1164 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Failed to get Routes: Link not found 2020-07-06T09:30:24.391+0300 DEBUG netlink/netlink.go:1145 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink DEL event for veth1540e49(26047) within f7523f74-b6ed-4f6b-4337-bcc85c22057f 2020-07-06T09:30:24.392+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for vethe9bd230(26048,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:24.393+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for veth1540e49(26047,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:24.403+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for vethe9bd230(26048,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:24.426+0300 WARN netlink/netlink.go:1164 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Failed to get Routes: Link not found 2020-07-06T09:30:24.426+0300 WARN netlink/netlink.go:1164 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Failed to get Routes: Link not found 2020-07-06T09:30:24.427+0300 WARN netlink/netlink.go:1164 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Failed to get Routes: Link not found 2020-07-06T09:30:24.427+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for vethe9bd230(26048,device) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:24.428+0300 DEBUG netlink/netlink.go:1145 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink DEL event for veth1540e49(26047) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:24.429+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for vethe9bd230(26048,device) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:24.429+0300 DEBUG netlink/netlink.go:1145 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink DEL event for vethe9bd230(26048) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:24.433+0300 DEBUG netlink/netlink.go:1145 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink DEL event for vethe9bd230(26048) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:24.907+0300 DEBUG tests/tests.go:328 execCmds skydivecicd1.sl.cloud9.ibm.com: Command returned test-skydive-docker-share-ns 2020-07-06T09:30:24.907+0300 DEBUG tests/tests.go:325 execCmds skydivecicd1.sl.cloud9.ibm.com: Executing command [docker rm -f test-skydive-docker-share-ns2] 2020-07-06T09:30:25.091+0300 DEBUG docker/docker.go:165 (*ProbeHandler).unregisterContainer skydivecicd1.sl.cloud9.ibm.com: Stop listening for namespace /proc/19447/ns/net with PID 19447 2020-07-06T09:30:25.091+0300 DEBUG netns/netns.go:216 (*ProbeHandler).Unregister skydivecicd1.sl.cloud9.ibm.com: Unregister network Namespace: /proc/19447/ns/net 2020-07-06T09:30:25.091+0300 DEBUG netns/netns.go:235 (*ProbeHandler).Unregister skydivecicd1.sl.cloud9.ibm.com: Decremented counter for namespace 3,4026533005 to 1 2020-07-06T09:30:25.460+0300 DEBUG tests/tests.go:328 execCmds skydivecicd1.sl.cloud9.ibm.com: Command returned test-skydive-docker-share-ns2 2020-07-06T09:30:25.463+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, topology, read ---> true --- PASS: TestDockerShareNamespace (5.54s) tests.go:479: Creating captures tests.go:495: Executing setup commands tests.go:512: Checking captures are correctly set up tests.go:577: Executing settle function tests.go:592: Executing setup function tests.go:726: Running checks tests.go:753: Running tear down commands tests.go:771: Replaying test with time 2020-07-06 09:30:24.116198428 +0300 IDT m=+42.798533791 (Unix: 1594017024), startTime 2020-07-06 09:30:24.105632866 +0300 IDT m=+42.787968205 (Unix: 1594017024) tests.go:646: Removing existing injections tests.go:473: Removing existing captures === RUN TestDockerNetHost 2020-07-06T09:30:25.702+0300 DEBUG tests/tests.go:325 execCmds skydivecicd1.sl.cloud9.ibm.com: Executing command [docker run -d -t -i --net=host --name test-skydive-docker-net-host busybox] 2020-07-06T09:30:26.488+0300 DEBUG tests/tests.go:328 execCmds skydivecicd1.sl.cloud9.ibm.com: Command returned bfa9d87b0a66710e6eae5ab3b1f3bf7278f681f166e68a50ca7802f32dc1507b 2020-07-06T09:30:26.488+0300 DEBUG docker/docker.go:87 (*ProbeHandler).registerContainer skydivecicd1.sl.cloud9.ibm.com: Register docker container bfa9d87b0a66710e6eae5ab3b1f3bf7278f681f166e68a50ca7802f32dc1507b and PID 19605 2020-07-06T09:30:26.489+0300 DEBUG netns/netns.go:133 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Register network namespace: /proc/19605/ns/net 2020-07-06T09:30:26.489+0300 DEBUG netns/netns.go:148 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: /proc/19605/ns/net is a privileged namespace 2020-07-06T09:30:28.492+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, topology, read ---> true 2020-07-06T09:30:28.501+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, topology, read ---> true 2020-07-06T09:30:28.504+0300 DEBUG tests/tests.go:325 execCmds skydivecicd1.sl.cloud9.ibm.com: Executing command [docker rm -f test-skydive-docker-net-host] 2020-07-06T09:30:28.671+0300 DEBUG docker/docker.go:165 (*ProbeHandler).unregisterContainer skydivecicd1.sl.cloud9.ibm.com: Stop listening for namespace /proc/19605/ns/net with PID 19605 2020-07-06T09:30:28.672+0300 DEBUG netns/netns.go:216 (*ProbeHandler).Unregister skydivecicd1.sl.cloud9.ibm.com: Unregister network Namespace: /proc/19605/ns/net 2020-07-06T09:30:29.068+0300 DEBUG tests/tests.go:328 execCmds skydivecicd1.sl.cloud9.ibm.com: Command returned test-skydive-docker-net-host 2020-07-06T09:30:29.069+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, topology, read ---> true 2020-07-06T09:30:29.080+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, topology, read ---> true --- PASS: TestDockerNetHost (3.39s) tests.go:479: Creating captures tests.go:495: Executing setup commands tests.go:512: Checking captures are correctly set up tests.go:577: Executing settle function tests.go:592: Executing setup function tests.go:726: Running checks tests.go:753: Running tear down commands tests.go:771: Replaying test with time 2020-07-06 09:30:28.504830434 +0300 IDT m=+47.187165763 (Unix: 1594017028), startTime 2020-07-06 09:30:28.488993449 +0300 IDT m=+47.171328805 (Unix: 1594017028) tests.go:646: Removing existing injections tests.go:473: Removing existing captures === RUN TestDockerLabels 2020-07-06T09:30:29.087+0300 DEBUG tests/tests.go:325 execCmds skydivecicd1.sl.cloud9.ibm.com: Executing command [docker run -d -t -i --label a.b.c=123 --label a~b/c@d=456 --name test-skydive-docker-labels busybox] 2020-07-06T09:30:29.537+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for veth9cb3919(26049,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:29.544+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for veth1fa5788(26050,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:29.546+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for veth1fa5788(26050,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:29.549+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for veth1fa5788(26050,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:29.553+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for veth1fa5788(26050,device) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:29.555+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for veth1fa5788(26050,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:29.557+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for veth1fa5788(26050,device) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:29.886+0300 DEBUG netns/netns.go:133 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Register network namespace: /var/run/docker/netns/1c4695292649 2020-07-06T09:30:29.887+0300 DEBUG netns/netns.go:168 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Network namespace added: 3,4026533086 2020-07-06T09:30:29.888+0300 DEBUG netns/netns.go:186 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Registering namespace: 3,4026533086 2020-07-06T09:30:29.888+0300 DEBUG netlink/netlink.go:1089 (*Probe).start skydivecicd1.sl.cloud9.ibm.com: Start polling netlink event for 2afe4369-073d-477a-7b32-479fe4a1fd28 2020-07-06T09:30:29.888+0300 DEBUG netlink/netlink.go:836 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize Netlink interfaces for 2afe4369-073d-477a-7b32-479fe4a1fd28 2020-07-06T09:30:29.889+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD lo(1,device) within 2afe4369-073d-477a-7b32-479fe4a1fd28 2020-07-06T09:30:29.889+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (lo): operation not supported 2020-07-06T09:30:29.891+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD gre0(2,gre) within 2afe4369-073d-477a-7b32-479fe4a1fd28 2020-07-06T09:30:29.891+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (gre0): operation not supported 2020-07-06T09:30:29.894+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD gretap0(3,gretap) within 2afe4369-073d-477a-7b32-479fe4a1fd28 2020-07-06T09:30:29.898+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (gretap0): operation not supported 2020-07-06T09:30:29.900+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD erspan0(4,erspan) within 2afe4369-073d-477a-7b32-479fe4a1fd28 2020-07-06T09:30:29.900+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (erspan0): operation not supported 2020-07-06T09:30:29.937+0300 DEBUG netlink/netlink.go:1145 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink DEL event for veth9cb3919(26049) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:29.939+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for veth9cb3919(26049,veth) within 2afe4369-073d-477a-7b32-479fe4a1fd28 2020-07-06T09:30:29.963+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for eth0(26049,veth) within 2afe4369-073d-477a-7b32-479fe4a1fd28 2020-07-06T09:30:29.965+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for eth0(26049,veth) within 2afe4369-073d-477a-7b32-479fe4a1fd28 2020-07-06T09:30:29.967+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for veth1fa5788(26050,device) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:29.969+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for veth1fa5788(26050,device) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:29.971+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for eth0(26049,veth) within 2afe4369-073d-477a-7b32-479fe4a1fd28 2020-07-06T09:30:29.972+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for veth1fa5788(26050,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:29.975+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for eth0(26049,veth) within 2afe4369-073d-477a-7b32-479fe4a1fd28 2020-07-06T09:30:30.214+0300 DEBUG tests/tests.go:328 execCmds skydivecicd1.sl.cloud9.ibm.com: Command returned 546b154bad0107d8a16c0f9b226f80e225b153aa5b7ffa2ea6b8a82d9b14a2a0 2020-07-06T09:30:30.214+0300 DEBUG docker/docker.go:87 (*ProbeHandler).registerContainer skydivecicd1.sl.cloud9.ibm.com: Register docker container 546b154bad0107d8a16c0f9b226f80e225b153aa5b7ffa2ea6b8a82d9b14a2a0 and PID 19712 2020-07-06T09:30:30.215+0300 DEBUG netns/netns.go:133 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Register network namespace: /proc/19712/ns/net 2020-07-06T09:30:30.215+0300 DEBUG netns/netns.go:164 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Increasing counter for namespace 3,4026533086 to 2 2020-07-06T09:30:32.217+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, topology, read ---> true 2020-07-06T09:30:32.226+0300 DEBUG tests/tests.go:325 execCmds skydivecicd1.sl.cloud9.ibm.com: Executing command [docker rm -f test-skydive-docker-labels] 2020-07-06T09:30:32.434+0300 DEBUG docker/docker.go:165 (*ProbeHandler).unregisterContainer skydivecicd1.sl.cloud9.ibm.com: Stop listening for namespace /proc/19712/ns/net with PID 19712 2020-07-06T09:30:32.434+0300 DEBUG netns/netns.go:216 (*ProbeHandler).Unregister skydivecicd1.sl.cloud9.ibm.com: Unregister network Namespace: /proc/19712/ns/net 2020-07-06T09:30:32.434+0300 DEBUG netns/netns.go:235 (*ProbeHandler).Unregister skydivecicd1.sl.cloud9.ibm.com: Decremented counter for namespace 3,4026533086 to 1 2020-07-06T09:30:32.452+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for eth0(26049,veth) within 2afe4369-073d-477a-7b32-479fe4a1fd28 2020-07-06T09:30:32.485+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for veth9cb3919(26049,veth) within 2afe4369-073d-477a-7b32-479fe4a1fd28 2020-07-06T09:30:32.485+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for veth1fa5788(26050,device) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:32.489+0300 WARN netlink/netlink.go:1164 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Failed to get Routes: Link not found 2020-07-06T09:30:32.490+0300 DEBUG netlink/netlink.go:1145 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink DEL event for veth9cb3919(26049) within 2afe4369-073d-477a-7b32-479fe4a1fd28 2020-07-06T09:30:32.490+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for veth1fa5788(26050,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:32.492+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for veth9cb3919(26049,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:32.502+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for veth1fa5788(26050,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:32.521+0300 WARN netlink/netlink.go:1164 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Failed to get Routes: Link not found 2020-07-06T09:30:32.521+0300 WARN netlink/netlink.go:1164 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Failed to get Routes: Link not found 2020-07-06T09:30:32.522+0300 WARN netlink/netlink.go:1164 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Failed to get Routes: Link not found 2020-07-06T09:30:32.522+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for veth1fa5788(26050,device) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:32.522+0300 DEBUG netlink/netlink.go:1145 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink DEL event for veth9cb3919(26049) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:32.524+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for veth1fa5788(26050,device) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:32.524+0300 DEBUG netlink/netlink.go:1145 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink DEL event for veth1fa5788(26050) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:32.527+0300 DEBUG netlink/netlink.go:1145 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink DEL event for veth1fa5788(26050) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:33.032+0300 DEBUG tests/tests.go:328 execCmds skydivecicd1.sl.cloud9.ibm.com: Command returned test-skydive-docker-labels 2020-07-06T09:30:33.034+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, topology, read ---> true 2020-07-06T09:30:34.042+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, topology, read ---> true 2020-07-06T09:30:35.055+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, topology, read ---> true 2020-07-06T09:30:36.072+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, topology, read ---> true --- PASS: TestDockerLabels (7.00s) tests.go:479: Creating captures tests.go:495: Executing setup commands tests.go:512: Checking captures are correctly set up tests.go:577: Executing settle function tests.go:592: Executing setup function tests.go:726: Running checks tests.go:753: Running tear down commands tests.go:771: Replaying test with time 2020-07-06 09:30:32.226393589 +0300 IDT m=+50.908728963 (Unix: 1594017032), startTime 2020-07-06 09:30:32.215220865 +0300 IDT m=+50.897556201 (Unix: 1594017032) tests.go:646: Removing existing injections tests.go:473: Removing existing captures === RUN TestRollingSimple 2020-07-06T09:30:39.792+0300 INFO elasticsearch/client.go:235 (*Client).start skydivecicd1.sl.cloud9.ibm.com: client started for skydive_rolling, skydive_not_rolling 2020-07-06T09:30:44.793+0300 DEBUG elasticsearch/rollindex.go:82 (*rollIndexService).roll skydivecicd1.sl.cloud9.ibm.com: Start rolling indices (forced: false)... 2020-07-06T09:30:44.793+0300 INFO elasticsearch/rollindex.go:104 (*rollIndexService).roll skydivecicd1.sl.cloud9.ibm.com: Index skydive_rolling rolling over 2020-07-06T09:30:44.793+0300 DEBUG elasticsearch/rollindex.go:106 (*rollIndexService).roll skydivecicd1.sl.cloud9.ibm.com: Rolling over with: &{client:0xc0002f89c0 pretty: human: errorTrace: filterPath:[] headers:map[] dryRun:false newIndex: alias:skydive_rolling masterTimeout: timeout: waitForActiveShards: conditions:map[max_docs:10] settings:map[] mappings:map[] bodyJson: bodyString:} 2020-07-06T09:30:45.967+0300 DEBUG elasticsearch/rollindex.go:82 (*rollIndexService).roll skydivecicd1.sl.cloud9.ibm.com: Start rolling indices (forced: false)... 2020-07-06T09:30:45.967+0300 INFO elasticsearch/rollindex.go:121 (*rollIndexService).roll skydivecicd1.sl.cloud9.ibm.com: Rolling indices done 2020-07-06T09:30:46.154+0300 INFO elasticsearch/rollindex.go:114 (*rollIndexService).roll skydivecicd1.sl.cloud9.ibm.com: Index skydive_rolling rolled over 2020-07-06T09:30:46.154+0300 INFO elasticsearch/rollindex.go:121 (*rollIndexService).roll skydivecicd1.sl.cloud9.ibm.com: Rolling indices done --- PASS: TestRollingSimple (11.17s) === RUN TestFlowsEBPF 2020-07-06T09:30:47.259+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, capture, write ---> true 2020-07-06T09:30:47.262+0300 DEBUG client/client.go:383 (*OnDemandClient).onAPIWatcherEvent skydivecicd1.sl.cloud9.ibm.com: New watcher event set for e9690f61-085a-46ad-7377-9103d4772383 2020-07-06T09:30:47.267+0300 DEBUG tests/tests.go:325 execCmds skydivecicd1.sl.cloud9.ibm.com: Executing command [ovs-vsctl add-br br-ebpf] 2020-07-06T09:30:47.514+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for ovs-system(26051,openvswitch) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:47.519+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for ovs-system(26051,openvswitch) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:47.527+0300 INFO ovsdb/ovsdb.go:388 (*OvsMonitor).portAdded skydivecicd1.sl.cloud9.ibm.com: New port "br-ebpf(6201215b-f757-4ef7-b7b8-52e65fcfe60f)" added 2020-07-06T09:30:47.528+0300 INFO ovsdb/ovsdb.go:279 (*OvsMonitor).bridgeAdded skydivecicd1.sl.cloud9.ibm.com: New bridge "br-ebpf(5a775089-8f53-408a-bf20-3f5772c52bf7)" added 2020-07-06T09:30:47.540+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for br-ebpf(26052,openvswitch) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:47.552+0300 DEBUG tests/tests.go:328 execCmds skydivecicd1.sl.cloud9.ibm.com: Command returned 2020-07-06T09:30:47.552+0300 DEBUG tests/tests.go:325 execCmds skydivecicd1.sl.cloud9.ibm.com: Executing command [ip netns add src-vm] 2020-07-06T09:30:47.553+0300 DEBUG netns/netns.go:133 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Register network namespace: /var/run/netns/src-vm 2020-07-06T09:30:47.555+0300 DEBUG tests/tests.go:328 execCmds skydivecicd1.sl.cloud9.ibm.com: Command returned 2020-07-06T09:30:47.555+0300 DEBUG tests/tests.go:325 execCmds skydivecicd1.sl.cloud9.ibm.com: Executing command [ip link add src-vm-eth0 type veth peer name ebpf-src-eth0 netns src-vm] 2020-07-06T09:30:47.557+0300 DEBUG tests/tests.go:328 execCmds skydivecicd1.sl.cloud9.ibm.com: Command returned 2020-07-06T09:30:47.557+0300 DEBUG tests/tests.go:325 execCmds skydivecicd1.sl.cloud9.ibm.com: Executing command [ip link set src-vm-eth0 up] 2020-07-06T09:30:47.560+0300 DEBUG tests/tests.go:328 execCmds skydivecicd1.sl.cloud9.ibm.com: Command returned 2020-07-06T09:30:47.560+0300 DEBUG tests/tests.go:325 execCmds skydivecicd1.sl.cloud9.ibm.com: Executing command [ip netns exec src-vm ip link set ebpf-src-eth0 up] 2020-07-06T09:30:47.565+0300 DEBUG tests/tests.go:328 execCmds skydivecicd1.sl.cloud9.ibm.com: Command returned 2020-07-06T09:30:47.565+0300 DEBUG tests/tests.go:325 execCmds skydivecicd1.sl.cloud9.ibm.com: Executing command [ip netns exec src-vm ip address add 169.254.107.33/24 dev ebpf-src-eth0] 2020-07-06T09:30:47.568+0300 DEBUG tests/tests.go:328 execCmds skydivecicd1.sl.cloud9.ibm.com: Command returned 2020-07-06T09:30:47.568+0300 DEBUG tests/tests.go:325 execCmds skydivecicd1.sl.cloud9.ibm.com: Executing command [ip netns add dst-vm] 2020-07-06T09:30:47.574+0300 DEBUG tests/tests.go:328 execCmds skydivecicd1.sl.cloud9.ibm.com: Command returned 2020-07-06T09:30:47.574+0300 DEBUG tests/tests.go:325 execCmds skydivecicd1.sl.cloud9.ibm.com: Executing command [ip link add dst-vm-eth0 type veth peer name ebpf-dst-eth0 netns dst-vm] 2020-07-06T09:30:47.575+0300 DEBUG netns/netns.go:168 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Network namespace added: 3,4026532837 2020-07-06T09:30:47.577+0300 DEBUG tests/tests.go:328 execCmds skydivecicd1.sl.cloud9.ibm.com: Command returned 2020-07-06T09:30:47.577+0300 DEBUG tests/tests.go:325 execCmds skydivecicd1.sl.cloud9.ibm.com: Executing command [ip link set dst-vm-eth0 up] 2020-07-06T09:30:47.581+0300 DEBUG tests/tests.go:328 execCmds skydivecicd1.sl.cloud9.ibm.com: Command returned 2020-07-06T09:30:47.581+0300 DEBUG tests/tests.go:325 execCmds skydivecicd1.sl.cloud9.ibm.com: Executing command [ip netns exec dst-vm ip link set ebpf-dst-eth0 up] 2020-07-06T09:30:47.588+0300 DEBUG tests/tests.go:328 execCmds skydivecicd1.sl.cloud9.ibm.com: Command returned 2020-07-06T09:30:47.588+0300 DEBUG tests/tests.go:325 execCmds skydivecicd1.sl.cloud9.ibm.com: Executing command [ip netns exec dst-vm ip address add 169.254.107.34/24 dev ebpf-dst-eth0] 2020-07-06T09:30:47.591+0300 DEBUG tests/tests.go:328 execCmds skydivecicd1.sl.cloud9.ibm.com: Command returned 2020-07-06T09:30:47.591+0300 DEBUG tests/tests.go:325 execCmds skydivecicd1.sl.cloud9.ibm.com: Executing command [ovs-vsctl add-port br-ebpf src-vm-eth0] 2020-07-06T09:30:47.608+0300 DEBUG tests/tests.go:328 execCmds skydivecicd1.sl.cloud9.ibm.com: Command returned 2020-07-06T09:30:47.608+0300 DEBUG tests/tests.go:325 execCmds skydivecicd1.sl.cloud9.ibm.com: Executing command [ovs-vsctl add-port br-ebpf dst-vm-eth0] 2020-07-06T09:30:47.613+0300 INFO ovsdb/ovsdb.go:431 (*OvsMonitor).ovsUpdate skydivecicd1.sl.cloud9.ibm.com: OpenvSwitch system updated 2020-07-06T09:30:47.622+0300 DEBUG tests/tests.go:328 execCmds skydivecicd1.sl.cloud9.ibm.com: Command returned 2020-07-06T09:30:47.624+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, topology, read ---> true 2020-07-06T09:30:47.630+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, topology, read ---> true 2020-07-06T09:30:47.642+0300 INFO openflow/client.go:313 (*Client).Start skydivecicd1.sl.cloud9.ibm.com: Successfully connected to OpenFlow switch unix:/var/run/openvswitch/br-ebpf.mgmt using version 5 2020-07-06T09:30:47.643+0300 INFO openflow/client.go:313 (*Client).Start skydivecicd1.sl.cloud9.ibm.com: Successfully connected to OpenFlow switch unix:/var/run/openvswitch/br-ebpf.mgmt using version 1 2020-07-06T09:30:47.643+0300 WARN ovsdb/ovs_of.go:99 (*OvsOfProbeHandler).newbridgeOfProbe skydivecicd1.sl.cloud9.ibm.com: Cannot add group probe on br-ebpf - Group monitoring is only possible on OpenFlow 1.5 and later because of an OVS bug 2020-07-06T09:30:47.643+0300 DEBUG ovsdb/ovs_of.go:132 (*OvsOfProbeHandler).OnOvsBridgeAdd skydivecicd1.sl.cloud9.ibm.com: Probe added for br-ebpf on /var/run/openvswitch/db.sock (5a775089-8f53-408a-bf20-3f5772c52bf7) 2020-07-06T09:30:47.644+0300 DEBUG ovsdb/of10.go:37 (*of10Handler).OnMessage skydivecicd1.sl.cloud9.ibm.com: Handling flow monitor (*of10.NiciraFlowMonitorReply)(0xc000b06860)({ NiciraStatsReply: (*of10.NiciraStatsReply)(0xc001622450)({ ExperimenterStatsReply: (*of10.ExperimenterStatsReply)(0xc001622440)({ StatsReply: (*of10.StatsReply)(0xc001622430)({ Header: (*of10.Header)(0xc000c54050)({ Version: (uint8) 1, Type: (uint8) 17, Length: (uint16) 56, Xid: (uint32) 2 }), StatsType: (uint16) 65535, Flags: (of10.StatsReplyFlags) 0 }), Experimenter: (uint32) 8992 }), Subtype: (uint32) 2 }), Updates: ([]of10.INiciraFlowUpdateEvent) (len=1 cap=1) { (*of10.NiciraFlowUpdateFullAdd)(0xc0009768c0)({ NiciraFlowUpdateEvent: (*of10.NiciraFlowUpdateEvent)(0xc000c54058)({ Length: (uint16) 32, Event: (uint16) 0 }), Reason: (uint16) 0, Priority: (uint16) 0, IdleTimeout: (uint16) 0, HardTimeout: (uint16) 0, MatchLen: (uint16) 0, TableId: (uint8) 0, Cookie: (uint64) 0, Match: (of10.NiciraMatch) { NxmEntries: ([]goloxi.IOxm) }, Actions: ([]goloxi.IAction) (len=1 cap=1) { (*of10.ActionOutput)(0xc001622460)({ Action: (*of10.Action)(0xc000c5405c)({ Type: (uint16) 0, Len: (uint16) 8 }), Port: (of10.Port) 65530, MaxLen: (uint16) 0 }) } }) } }) 2020-07-06T09:30:47.644+0300 INFO ovsdb/ovsdb.go:268 (*OvsMonitor).bridgeUpdated skydivecicd1.sl.cloud9.ibm.com: Bridge "br-ebpf(5a775089-8f53-408a-bf20-3f5772c52bf7)" updated 2020-07-06T09:30:47.645+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for br-ebpf(26052,openvswitch) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:47.649+0300 DEBUG netns/netns.go:186 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Registering namespace: 3,4026532837 2020-07-06T09:30:47.649+0300 WARN ovsdb/ovs_of.go:119 (*OvsOfProbeHandler).OnOvsBridgeAdd skydivecicd1.sl.cloud9.ibm.com: Cannot add group probe on br-ebpf - Group monitoring is only possible on OpenFlow 1.5 and later because of an OVS bug 2020-07-06T09:30:47.650+0300 INFO ovsdb/ovsdb.go:268 (*OvsMonitor).bridgeUpdated skydivecicd1.sl.cloud9.ibm.com: Bridge "br-ebpf(5a775089-8f53-408a-bf20-3f5772c52bf7)" updated 2020-07-06T09:30:47.651+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for br-ebpf(26052,openvswitch) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:47.651+0300 DEBUG netlink/netlink.go:1089 (*Probe).start skydivecicd1.sl.cloud9.ibm.com: Start polling netlink event for 5be77bc7-83a9-48c3-616b-11eed3e4802a 2020-07-06T09:30:47.651+0300 DEBUG netlink/netlink.go:836 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize Netlink interfaces for 5be77bc7-83a9-48c3-616b-11eed3e4802a 2020-07-06T09:30:47.651+0300 DEBUG netns/netns.go:133 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Register network namespace: /var/run/netns/dst-vm 2020-07-06T09:30:47.651+0300 DEBUG netns/netns.go:168 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Network namespace added: 3,4026533248 2020-07-06T09:30:47.652+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD lo(1,device) within 5be77bc7-83a9-48c3-616b-11eed3e4802a 2020-07-06T09:30:47.652+0300 WARN ovsdb/ovs_of.go:119 (*OvsOfProbeHandler).OnOvsBridgeAdd skydivecicd1.sl.cloud9.ibm.com: Cannot add group probe on br-ebpf - Group monitoring is only possible on OpenFlow 1.5 and later because of an OVS bug 2020-07-06T09:30:47.652+0300 INFO ovsdb/ovsdb.go:334 (*OvsMonitor).interfaceAdded skydivecicd1.sl.cloud9.ibm.com: New interface "br-ebpf(218a5d25-e29b-44c2-88fa-f2dfb39d07c9)" added 2020-07-06T09:30:47.653+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for src-vm-eth0(26053,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:47.654+0300 DEBUG netns/netns.go:186 (*ProbeHandler).Register skydivecicd1.sl.cloud9.ibm.com: Registering namespace: 3,4026533248 2020-07-06T09:30:47.654+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (lo): operation not supported 2020-07-06T09:30:47.655+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD gre0(2,gre) within 5be77bc7-83a9-48c3-616b-11eed3e4802a 2020-07-06T09:30:47.656+0300 INFO ovsdb/ovsdb.go:431 (*OvsMonitor).ovsUpdate skydivecicd1.sl.cloud9.ibm.com: OpenvSwitch system updated 2020-07-06T09:30:47.656+0300 INFO ovsdb/ovsdb.go:268 (*OvsMonitor).bridgeUpdated skydivecicd1.sl.cloud9.ibm.com: Bridge "br-ebpf(5a775089-8f53-408a-bf20-3f5772c52bf7)" updated 2020-07-06T09:30:47.658+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for src-vm-eth0(26053,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:47.658+0300 DEBUG netlink/netlink.go:1089 (*Probe).start skydivecicd1.sl.cloud9.ibm.com: Start polling netlink event for d2436be3-739e-4d64-664a-b496d6922d7a 2020-07-06T09:30:47.658+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (gre0): operation not supported 2020-07-06T09:30:47.658+0300 DEBUG netlink/netlink.go:836 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize Netlink interfaces for d2436be3-739e-4d64-664a-b496d6922d7a 2020-07-06T09:30:47.659+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD lo(1,device) within d2436be3-739e-4d64-664a-b496d6922d7a 2020-07-06T09:30:47.659+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD gretap0(3,gretap) within 5be77bc7-83a9-48c3-616b-11eed3e4802a 2020-07-06T09:30:47.660+0300 WARN ovsdb/ovs_of.go:119 (*OvsOfProbeHandler).OnOvsBridgeAdd skydivecicd1.sl.cloud9.ibm.com: Cannot add group probe on br-ebpf - Group monitoring is only possible on OpenFlow 1.5 and later because of an OVS bug 2020-07-06T09:30:47.660+0300 INFO ovsdb/ovsdb.go:268 (*OvsMonitor).bridgeUpdated skydivecicd1.sl.cloud9.ibm.com: Bridge "br-ebpf(5a775089-8f53-408a-bf20-3f5772c52bf7)" updated 2020-07-06T09:30:47.663+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (lo): operation not supported 2020-07-06T09:30:47.664+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD gre0(2,gre) within d2436be3-739e-4d64-664a-b496d6922d7a 2020-07-06T09:30:47.664+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (gre0): operation not supported 2020-07-06T09:30:47.665+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD gretap0(3,gretap) within d2436be3-739e-4d64-664a-b496d6922d7a 2020-07-06T09:30:47.666+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (gretap0): operation not supported 2020-07-06T09:30:47.667+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD erspan0(4,erspan) within 5be77bc7-83a9-48c3-616b-11eed3e4802a 2020-07-06T09:30:47.667+0300 WARN ovsdb/ovs_of.go:119 (*OvsOfProbeHandler).OnOvsBridgeAdd skydivecicd1.sl.cloud9.ibm.com: Cannot add group probe on br-ebpf - Group monitoring is only possible on OpenFlow 1.5 and later because of an OVS bug 2020-07-06T09:30:47.667+0300 INFO ovsdb/ovsdb.go:334 (*OvsMonitor).interfaceAdded skydivecicd1.sl.cloud9.ibm.com: New interface "src-vm-eth0(c20f2cb3-03d3-4555-bd7d-63a45561c23b)" added 2020-07-06T09:30:47.668+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (gretap0): operation not supported 2020-07-06T09:30:47.669+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD erspan0(4,erspan) within d2436be3-739e-4d64-664a-b496d6922d7a 2020-07-06T09:30:47.670+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (erspan0): operation not supported 2020-07-06T09:30:47.671+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD ebpf-src-eth0(5,veth) within 5be77bc7-83a9-48c3-616b-11eed3e4802a 2020-07-06T09:30:47.671+0300 INFO ovsdb/ovsdb.go:431 (*OvsMonitor).ovsUpdate skydivecicd1.sl.cloud9.ibm.com: OpenvSwitch system updated 2020-07-06T09:30:47.672+0300 INFO ovsdb/ovsdb.go:323 (*OvsMonitor).interfaceUpdated skydivecicd1.sl.cloud9.ibm.com: Interface "src-vm-eth0(c20f2cb3-03d3-4555-bd7d-63a45561c23b)" updated 2020-07-06T09:30:47.672+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for src-vm-eth0(26053,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:47.672+0300 DEBUG netlink/netlink.go:574 (*Probe).addLinkToTopology skydivecicd1.sl.cloud9.ibm.com: Unable get Bus Info from ethtool (erspan0): operation not supported 2020-07-06T09:30:47.673+0300 DEBUG netlink/netlink.go:846 (*Probe).initialize skydivecicd1.sl.cloud9.ibm.com: Initialize ADD ebpf-dst-eth0(5,veth) within d2436be3-739e-4d64-664a-b496d6922d7a 2020-07-06T09:30:47.676+0300 INFO ovsdb/ovsdb.go:323 (*OvsMonitor).interfaceUpdated skydivecicd1.sl.cloud9.ibm.com: Interface "src-vm-eth0(c20f2cb3-03d3-4555-bd7d-63a45561c23b)" updated 2020-07-06T09:30:47.678+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for dst-vm-eth0(26054,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:47.681+0300 INFO ovsdb/ovsdb.go:431 (*OvsMonitor).ovsUpdate skydivecicd1.sl.cloud9.ibm.com: OpenvSwitch system updated 2020-07-06T09:30:47.681+0300 INFO ovsdb/ovsdb.go:268 (*OvsMonitor).bridgeUpdated skydivecicd1.sl.cloud9.ibm.com: Bridge "br-ebpf(5a775089-8f53-408a-bf20-3f5772c52bf7)" updated 2020-07-06T09:30:47.683+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for dst-vm-eth0(26054,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:47.683+0300 WARN ovsdb/ovs_of.go:119 (*OvsOfProbeHandler).OnOvsBridgeAdd skydivecicd1.sl.cloud9.ibm.com: Cannot add group probe on br-ebpf - Group monitoring is only possible on OpenFlow 1.5 and later because of an OVS bug 2020-07-06T09:30:47.683+0300 INFO ovsdb/ovsdb.go:334 (*OvsMonitor).interfaceAdded skydivecicd1.sl.cloud9.ibm.com: New interface "dst-vm-eth0(28df590b-b9aa-45fc-944c-b8bca8832577)" added 2020-07-06T09:30:47.686+0300 INFO ovsdb/ovsdb.go:431 (*OvsMonitor).ovsUpdate skydivecicd1.sl.cloud9.ibm.com: OpenvSwitch system updated 2020-07-06T09:30:47.686+0300 INFO ovsdb/ovsdb.go:268 (*OvsMonitor).bridgeUpdated skydivecicd1.sl.cloud9.ibm.com: Bridge "br-ebpf(5a775089-8f53-408a-bf20-3f5772c52bf7)" updated 2020-07-06T09:30:47.687+0300 WARN ovsdb/ovs_of.go:119 (*OvsOfProbeHandler).OnOvsBridgeAdd skydivecicd1.sl.cloud9.ibm.com: Cannot add group probe on br-ebpf - Group monitoring is only possible on OpenFlow 1.5 and later because of an OVS bug 2020-07-06T09:30:47.687+0300 INFO ovsdb/ovsdb.go:268 (*OvsMonitor).bridgeUpdated skydivecicd1.sl.cloud9.ibm.com: Bridge "br-ebpf(5a775089-8f53-408a-bf20-3f5772c52bf7)" updated 2020-07-06T09:30:47.687+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for dst-vm-eth0(26054,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:47.688+0300 WARN ovsdb/ovs_of.go:119 (*OvsOfProbeHandler).OnOvsBridgeAdd skydivecicd1.sl.cloud9.ibm.com: Cannot add group probe on br-ebpf - Group monitoring is only possible on OpenFlow 1.5 and later because of an OVS bug 2020-07-06T09:30:47.688+0300 INFO ovsdb/ovsdb.go:323 (*OvsMonitor).interfaceUpdated skydivecicd1.sl.cloud9.ibm.com: Interface "dst-vm-eth0(28df590b-b9aa-45fc-944c-b8bca8832577)" updated 2020-07-06T09:30:47.690+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for src-vm-eth0(26053,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:47.690+0300 INFO ovsdb/ovsdb.go:431 (*OvsMonitor).ovsUpdate skydivecicd1.sl.cloud9.ibm.com: OpenvSwitch system updated 2020-07-06T09:30:47.690+0300 INFO ovsdb/ovsdb.go:323 (*OvsMonitor).interfaceUpdated skydivecicd1.sl.cloud9.ibm.com: Interface "br-ebpf(218a5d25-e29b-44c2-88fa-f2dfb39d07c9)" updated 2020-07-06T09:30:47.693+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for src-vm-eth0(26053,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:47.694+0300 INFO ovsdb/ovsdb.go:431 (*OvsMonitor).ovsUpdate skydivecicd1.sl.cloud9.ibm.com: OpenvSwitch system updated 2020-07-06T09:30:47.694+0300 INFO ovsdb/ovsdb.go:323 (*OvsMonitor).interfaceUpdated skydivecicd1.sl.cloud9.ibm.com: Interface "br-ebpf(218a5d25-e29b-44c2-88fa-f2dfb39d07c9)" updated 2020-07-06T09:30:47.696+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for dst-vm-eth0(26054,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:47.697+0300 INFO ovsdb/ovsdb.go:431 (*OvsMonitor).ovsUpdate skydivecicd1.sl.cloud9.ibm.com: OpenvSwitch system updated 2020-07-06T09:30:47.697+0300 INFO ovsdb/ovsdb.go:323 (*OvsMonitor).interfaceUpdated skydivecicd1.sl.cloud9.ibm.com: Interface "br-ebpf(218a5d25-e29b-44c2-88fa-f2dfb39d07c9)" updated 2020-07-06T09:30:47.699+0300 DEBUG netlink/netlink.go:1137 (*Probe).onMessageAvailable skydivecicd1.sl.cloud9.ibm.com: Netlink ADD event for dst-vm-eth0(26054,veth) within b8a2dc2f-57e2-442d-42d1-9b781cca3c4c 2020-07-06T09:30:47.701+0300 INFO ovsdb/ovsdb.go:268 (*OvsMonitor).bridgeUpdated skydivecicd1.sl.cloud9.ibm.com: Bridge "br-ebpf(5a775089-8f53-408a-bf20-3f5772c52bf7)" updated 2020-07-06T09:30:47.702+0300 WARN ovsdb/ovs_of.go:119 (*OvsOfProbeHandler).OnOvsBridgeAdd skydivecicd1.sl.cloud9.ibm.com: Cannot add group probe on br-ebpf - Group monitoring is only possible on OpenFlow 1.5 and later because of an OVS bug 2020-07-06T09:30:47.703+0300 INFO ovsdb/ovsdb.go:323 (*OvsMonitor).interfaceUpdated skydivecicd1.sl.cloud9.ibm.com: Interface "br-ebpf(218a5d25-e29b-44c2-88fa-f2dfb39d07c9)" updated 2020-07-06T09:30:47.704+0300 INFO ovsdb/ovsdb.go:431 (*OvsMonitor).ovsUpdate skydivecicd1.sl.cloud9.ibm.com: OpenvSwitch system updated 2020-07-06T09:30:47.704+0300 INFO ovsdb/ovsdb.go:323 (*OvsMonitor).interfaceUpdated skydivecicd1.sl.cloud9.ibm.com: Interface "br-ebpf(218a5d25-e29b-44c2-88fa-f2dfb39d07c9)" updated 2020-07-06T09:30:47.704+0300 INFO ovsdb/ovsdb.go:388 (*OvsMonitor).portAdded skydivecicd1.sl.cloud9.ibm.com: New port "src-vm-eth0(627beb4c-425c-44db-b5f0-0eccff36177b)" added 2020-07-06T09:30:47.706+0300 INFO ovsdb/ovsdb.go:323 (*OvsMonitor).interfaceUpdated skydivecicd1.sl.cloud9.ibm.com: Interface "src-vm-eth0(c20f2cb3-03d3-4555-bd7d-63a45561c23b)" updated 2020-07-06T09:30:47.706+0300 INFO ovsdb/ovsdb.go:431 (*OvsMonitor).ovsUpdate skydivecicd1.sl.cloud9.ibm.com: OpenvSwitch system updated 2020-07-06T09:30:47.706+0300 INFO ovsdb/ovsdb.go:323 (*OvsMonitor).interfaceUpdated skydivecicd1.sl.cloud9.ibm.com: Interface "dst-vm-eth0(28df590b-b9aa-45fc-944c-b8bca8832577)" updated 2020-07-06T09:30:47.707+0300 INFO ovsdb/ovsdb.go:431 (*OvsMonitor).ovsUpdate skydivecicd1.sl.cloud9.ibm.com: OpenvSwitch system updated 2020-07-06T09:30:47.707+0300 INFO ovsdb/ovsdb.go:323 (*OvsMonitor).interfaceUpdated skydivecicd1.sl.cloud9.ibm.com: Interface "dst-vm-eth0(28df590b-b9aa-45fc-944c-b8bca8832577)" updated 2020-07-06T09:30:47.708+0300 INFO ovsdb/ovsdb.go:431 (*OvsMonitor).ovsUpdate skydivecicd1.sl.cloud9.ibm.com: OpenvSwitch system updated 2020-07-06T09:30:47.708+0300 INFO ovsdb/ovsdb.go:377 (*OvsMonitor).portUpdated skydivecicd1.sl.cloud9.ibm.com: Port "br-ebpf(6201215b-f757-4ef7-b7b8-52e65fcfe60f)" updated 2020-07-06T09:30:47.709+0300 INFO ovsdb/ovsdb.go:268 (*OvsMonitor).bridgeUpdated skydivecicd1.sl.cloud9.ibm.com: Bridge "br-ebpf(5a775089-8f53-408a-bf20-3f5772c52bf7)" updated 2020-07-06T09:30:47.710+0300 WARN ovsdb/ovs_of.go:119 (*OvsOfProbeHandler).OnOvsBridgeAdd skydivecicd1.sl.cloud9.ibm.com: Cannot add group probe on br-ebpf - Group monitoring is only possible on OpenFlow 1.5 and later because of an OVS bug 2020-07-06T09:30:47.710+0300 INFO ovsdb/ovsdb.go:377 (*OvsMonitor).portUpdated skydivecicd1.sl.cloud9.ibm.com: Port "src-vm-eth0(627beb4c-425c-44db-b5f0-0eccff36177b)" updated 2020-07-06T09:30:47.710+0300 INFO ovsdb/ovsdb.go:388 (*OvsMonitor).portAdded skydivecicd1.sl.cloud9.ibm.com: New port "dst-vm-eth0(04297903-5445-422a-bf46-5e471941c433)" added 2020-07-06T09:30:47.712+0300 INFO ovsdb/ovsdb.go:377 (*OvsMonitor).portUpdated skydivecicd1.sl.cloud9.ibm.com: Port "dst-vm-eth0(04297903-5445-422a-bf46-5e471941c433)" updated 2020-07-06T09:30:48.468+0300 DEBUG client/client.go:164 (*OnDemandClient).registerTask skydivecicd1.sl.cloud9.ibm.com: Registered task on cf5c30a7-3fb1-4e1e-5356-bc9607dcf2b2 with resource e9690f61-085a-46ad-7377-9103d4772383 2020-07-06T09:30:48.468+0300 DEBUG server/server.go:68 (*OnDemandServer).registerTask skydivecicd1.sl.cloud9.ibm.com: Attempting to register Capture e9690f61-085a-46ad-7377-9103d4772383 on node cf5c30a7-3fb1-4e1e-5356-bc9607dcf2b2 2020-07-06T09:30:48.559+0300 INFO ebpf/ebpf.go:385 (*ProbesHandler).loadModuleFromAsset skydivecicd1.sl.cloud9.ibm.com: Loaded eBPF module ebpf/flow-gre.o 2020-07-06T09:30:48.583+0300 DEBUG server/server.go:104 (*OnDemandServer).registerTask skydivecicd1.sl.cloud9.ibm.com: New active task on: {"ID":"cf5c30a7-3fb1-4e1e-5356-bc9607dcf2b2","Metadata":{"Metric":{"RxBytes":90,"RxPackets":1,"TxBytes":90,"TxPackets":1},"Type":"veth","EncapType":"ether","MTU":1500,"MAC":"f6:13:44:be:d8:ce","Speed":10000,"FDB":[{"Flags":["NTF_SELF"],"MAC":"33:33:00:00:00:01","State":["NUD_PERMANENT"],"IfIndex":5},{"Flags":["NTF_SELF"],"MAC":"01:00:5e:00:00:01","State":["NUD_PERMANENT"],"IfIndex":5},{"Flags":["NTF_SELF"],"MAC":"33:33:ff:be:d8:ce","State":["NUD_PERMANENT"],"IfIndex":5}],"Neighbors":[{"MAC":"33:33:00:00:00:16","IP":"ff02::16","State":["NUD_NOARP"],"IfIndex":5}],"State":"UP","TID":"47530d73-74ad-51d1-4601-aa091257df38","Driver":"veth","ParentIndex":26053,"RoutingTables":[{"ID":254,"Src":"169.254.107.33","Routes":[{"Protocol":2,"Prefix":"169.254.107.0/24","NextHops":[{"Priority":0,"IfIndex":5}]},{"Protocol":2,"Prefix":"fe80::/64","NextHops":[{"Priority":256,"IfIndex":5}]}]},{"ID":255,"Src":"169.254.107.33","Routes":[{"Protocol":2,"Prefix":"169.254.107.0/32","NextHops":[{"Priority":0,"IfIndex":5}]},{"Protocol":2,"Prefix":"169.254.107.33/32","NextHops":[{"Priority":0,"IfIndex":5}]},{"Protocol":2,"Prefix":"169.254.107.255/32","NextHops":[{"Priority":0,"IfIndex":5}]},{"Protocol":3,"Prefix":"ff00::/8","NextHops":[{"Priority":256,"IfIndex":5}]}]}],"IPV6":["fe80::f413:44ff:febe:d8ce/64"],"Name":"ebpf-src-eth0","PeerIfIndex":26053,"LinkFlags":["UP","BROADCAST"],"LinkNetNsID":0,"LinkNetNsName":"","IfIndex":5,"IPV4":["169.254.107.33/24"],"BusInfo":""},"Host":"skydivecicd1.sl.cloud9.ibm.com","Origin":"agent.skydivecicd1.sl.cloud9.ibm.com","CreatedAt":1594017047674,"UpdatedAt":1594017047674,"DeletedAt":null,"Revision":2} (&{{e9690f61-085a-46ad-7377-9103d4772383} G.V().Has("Name", "ebpf-src-eth0") ebpf 0 0 0 0 0 0 false false false L2 0 }) 2020-07-06T09:30:48.584+0300 DEBUG client/client.go:122 (*OnDemandClient).OnStructMessage skydivecicd1.sl.cloud9.ibm.com: Capture start request succeeded Namespace OnDemandCapture Type StartReply UUID 18dba06b-5903-4abe-53d2-ef7455bb5627 Status 200 Obj (307 bytes) 2020-07-06T09:30:48.821+0300 DEBUG config/rbac.go:50 (*logger).Print skydivecicd1.sl.cloud9.ibm.com: Request: admin, topology, read ---> true panic: interface conversion: interface {} is []interface {}, not *probes.Captures goroutine 414 [running]: github.com/skydive-project/skydive/flow/ondemand/client.(*onDemandFlowHandler).CheckState(0xc0001191a0, 0xc0001f3290, 0x7d318a0, 0xc001939c70, 0xc00044c998) /var/lib/jenkins/workspace/skydive-functional-tests-backend-elasticsearch/src/github.com/skydive-project/skydive/flow/ondemand/client/client.go:57 +0x36e github.com/skydive-project/skydive/graffiti/ondemand/client.(*OnDemandClient).OnNodeUpdated(0xc000209380, 0xc0001f3290, 0xc000ab91d0, 0x1, 0x1) /var/lib/jenkins/workspace/skydive-functional-tests-backend-elasticsearch/src/github.com/skydive-project/skydive/graffiti/ondemand/client/client.go:274 +0x2ca github.com/skydive-project/skydive/graffiti/graph.(*EventHandler).notifyListeners(0xc0005891d0, 0x1, 0x7244a00, 0xc0001f3290, 0x0, 0x0, 0xc000ab91d0, 0x1, 0x1) /var/lib/jenkins/workspace/skydive-functional-tests-backend-elasticsearch/src/github.com/skydive-project/skydive/graffiti/graph/graph.go:257 +0x2d4 github.com/skydive-project/skydive/graffiti/graph.(*EventHandler).NotifyEvent(0xc0005891d0, 0x1, 0x7244a00, 0xc0001f3290, 0xc000ab91d0, 0x1, 0x1) /var/lib/jenkins/workspace/skydive-functional-tests-backend-elasticsearch/src/github.com/skydive-project/skydive/graffiti/graph/graph.go:288 +0x2af github.com/skydive-project/skydive/graffiti/graph.(*MetadataTransaction).Commit(0xc002229d50, 0xc000ab91a0, 0xc000c55578) /var/lib/jenkins/workspace/skydive-functional-tests-backend-elasticsearch/src/github.com/skydive-project/skydive/graffiti/graph/transaction.go:93 +0x8de github.com/skydive-project/skydive/graffiti/common.(*PublisherEndpoint).OnStructMessage(0xc0005f56e0, 0x7d8cbe0, 0xc000a58d70, 0xc0018b06e0) /var/lib/jenkins/workspace/skydive-functional-tests-backend-elasticsearch/src/github.com/skydive-project/skydive/graffiti/common/publisher_endpoint.go:175 +0x14c0 github.com/skydive-project/skydive/graffiti/websocket.(*structSpeakerEventDispatcher).dispatchMessage(0xc000a17580, 0xc000a58d70, 0xc0018b06e0) /var/lib/jenkins/workspace/skydive-functional-tests-backend-elasticsearch/src/github.com/skydive-project/skydive/graffiti/websocket/message.go:273 +0x300 github.com/skydive-project/skydive/graffiti/websocket.(*StructSpeaker).OnMessage(0xc000a58d70, 0x7d8cbe0, 0xc000a58d70, 0x7c95180, 0xc001a14540) /var/lib/jenkins/workspace/skydive-functional-tests-backend-elasticsearch/src/github.com/skydive-project/skydive/graffiti/websocket/message.go:389 +0x2d5 github.com/skydive-project/skydive/graffiti/websocket.(*Conn).run.func2(0xc001adac00, 0x12d, 0x600, 0x0, 0x0) /var/lib/jenkins/workspace/skydive-functional-tests-backend-elasticsearch/src/github.com/skydive-project/skydive/graffiti/websocket/client.go:355 +0x164 github.com/skydive-project/skydive/graffiti/websocket.(*Conn).run.func5(0xc0008bb8c0, 0xc000b74d80, 0xc0007dbac0) /var/lib/jenkins/workspace/skydive-functional-tests-backend-elasticsearch/src/github.com/skydive-project/skydive/graffiti/websocket/client.go:399 +0xac created by github.com/skydive-project/skydive/graffiti/websocket.(*Conn).run /var/lib/jenkins/workspace/skydive-functional-tests-backend-elasticsearch/src/github.com/skydive-project/skydive/graffiti/websocket/client.go:395 +0x226 make[1]: *** [.mk/tests.mk:79: test.functionals.run] Error 2 make[1]: Leaving directory '/var/lib/jenkins/workspace/skydive-functional-tests-backend-elasticsearch/src/github.com/skydive-project/skydive' make: *** [.mk/tests.mk:87: test.functionals.batch] Error 2 go get: -f flag is a no-op when using modules es_cleanup elasticsearch elasticsearch Build step 'Execute shell' marked build as failure Recording test results Setting status of 6be367d569db43275c9a7074a984a8d1b35c284b to FAILURE with url http://vps736962.ovh.net:8080/job/skydive-functional-tests-backend-elasticsearch/421/ and message: 'Build finished. ' Using context: skydive-functional-tests-backend-elasticsearch Setting status of 6be367d569db43275c9a7074a984a8d1b35c284b to FAILURE with url http://ci-logs.skydive.network/logs/skydive-functional-tests-backend-elasticsearch/421 and message: ' ' Using context: skydive-functional-tests-backend-elasticsearch [Slack Notifications] found #420 as previous completed, non-aborted build [Slack Notifications] will send OnEveryFailureNotification because build matches and user preferences allow it Finished: FAILURE