Skip to content

Commit

Permalink
Improve logging gathering: (#362)
Browse files Browse the repository at this point in the history
Adding reporter that will dump all relevant logs to files that matches logtype
   On ci logs folder will be copied to artifacts

Signed-off-by: Igal Tsoiref <[email protected]>
  • Loading branch information
tsorya authored Jan 31, 2020
1 parent cc3f2f9 commit c23b1e2
Show file tree
Hide file tree
Showing 9 changed files with 163 additions and 39 deletions.
4 changes: 4 additions & 0 deletions .gitignore
Original file line number Diff line number Diff line change
Expand Up @@ -81,4 +81,8 @@ tags
### VisualStudioCode ###
.vscode/*
.history

### Test logs ###
test_logs

# End of https://www.gitignore.io/api/go,vim,emacs,visualstudiocode
1 change: 1 addition & 0 deletions Makefile
Original file line number Diff line number Diff line change
Expand Up @@ -101,6 +101,7 @@ test/unit: $(GINKGO)
test/e2e: $(OPERATOR_SDK)
# We have to unset mod=vendor here since operator-sdk is already
# building with it, and go tool fail if it's specified twice
mkdir -p test_logs/e2e
unset GOFLAGS && $(OPERATOR_SDK) test local ./test/e2e \
--kubeconfig $(KUBECONFIG) \
--namespace nmstate \
Expand Down
1 change: 1 addition & 0 deletions automation/check-patch.e2e-k8s.sh
Original file line number Diff line number Diff line change
Expand Up @@ -10,6 +10,7 @@
teardown() {
make cluster-down
cp $(find . -name "*junit*.xml") $ARTIFACTS
[ -d ${E2E_LOGS} ] && cp ${E2E_LOGS}/*.log ${ARTIFACTS}
}

main() {
Expand Down
1 change: 1 addition & 0 deletions automation/check-patch.e2e-ocp.sh
Original file line number Diff line number Diff line change
Expand Up @@ -10,6 +10,7 @@
teardown() {
make cluster-down
cp $(find . -name "*junit*.xml") $ARTIFACTS
[ -d ${E2E_LOGS} ] && cp ${E2E_LOGS}/*.log ${ARTIFACTS}
}

main() {
Expand Down
1 change: 1 addition & 0 deletions automation/check-patch.e2e-okd.sh
Original file line number Diff line number Diff line change
Expand Up @@ -13,6 +13,7 @@ exit 0
teardown() {
make cluster-down
cp $(find . -name "*junit*.xml") $ARTIFACTS
[ -d ${E2E_LOGS} ] && cp ${E2E_LOGS}/*.log ${ARTIFACTS}
}

main() {
Expand Down
1 change: 1 addition & 0 deletions automation/check-patch.setup.sh
Original file line number Diff line number Diff line change
Expand Up @@ -9,6 +9,7 @@ rm -rf $tmp_dir
mkdir -p $tmp_dir

export TMP_PROJECT_PATH=$tmp_dir/kubernetes-nmstate
export E2E_LOGS=${TMP_PROJECT_PATH}/test_logs/e2e
export ARTIFACTS=${ARTIFACTS-$tmp_dir/artifacts}
mkdir -p $ARTIFACTS

Expand Down
5 changes: 4 additions & 1 deletion test/e2e/main_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -36,6 +36,7 @@ var (
secondSecondaryNic = flag.String("secondSecondaryNic", "eth2", "Second secondary network interface name")
nodesInterfacesState = make(map[string][]byte)
interfacesToIgnore = []string{"flannel.1", "dummy0"}
reporter = NewKubernetesNMStateReporter("test_logs/e2e")
)

var _ = BeforeSuite(func() {
Expand All @@ -48,6 +49,7 @@ var _ = BeforeSuite(func() {
nodeList := corev1.NodeList{}
err = framework.Global.Client.List(context.TODO(), &nodeList, &dynclient.ListOptions{})
Expect(err).ToNot(HaveOccurred())
reporter.BeforeSuiteDidRun()
for _, node := range nodeList.Items {
nodes = append(nodes, node.Name)
}
Expand Down Expand Up @@ -75,6 +77,7 @@ var _ = BeforeEach(func() {
nodeState := nodeInterfacesState(node, interfacesToIgnore)
nodesInterfacesState[node] = nodeState
}
reporter.dumpStateBeforeEach(getTestName())

})

Expand All @@ -83,8 +86,8 @@ var _ = AfterEach(func() {
for _, node := range nodes {
nodeState := nodeInterfacesState(node, interfacesToIgnore)
Expect(nodesInterfacesState[node]).Should(MatchJSON(nodeState))
writePodsLogs(namespace, startTime, GinkgoWriter)
}
reporter.dumpStateAfterEach(getTestName(), namespace, startTime)
})

func getMaxFailsFromEnv() int {
Expand Down
143 changes: 143 additions & 0 deletions test/e2e/reporter.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,143 @@
package e2e

import (
"context"
"fmt"
. "github.com/onsi/ginkgo"
. "github.com/onsi/gomega"
framework "github.com/operator-framework/operator-sdk/pkg/test"
"io"
"io/ioutil"
corev1 "k8s.io/api/core/v1"
metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
"os"
"path"
dynclient "sigs.k8s.io/controller-runtime/pkg/client"
"strings"
"time"
)

type KubernetesNMStateReporter struct {
artifactsDir string
}

func NewKubernetesNMStateReporter(artifactsDir string) *KubernetesNMStateReporter {
return &KubernetesNMStateReporter{
artifactsDir: artifactsDir,
}
}

func (r *KubernetesNMStateReporter) BeforeSuiteDidRun() {
r.Cleanup()
}

func (r *KubernetesNMStateReporter) dumpStateBeforeEach(testName string) {
r.logDeviceStatus(testName)
}

func (r *KubernetesNMStateReporter) dumpStateAfterEach(testName string, namespace string, testStartTime time.Time) {
r.logPods(testName, namespace, testStartTime)
r.logDeviceStatus(testName)
r.logNetworkManager(testName, testStartTime)
}

func (r *KubernetesNMStateReporter) logDeviceStatus(testName string) {

r.OpenTestLogFile("deviceStatus", testName, func(writer io.ReadWriteCloser) {
writer.Write([]byte(fmt.Sprintf("\n***** Start printing device status *****\n\n")))
for _, node := range nodes {
output, err := runAtNode(node, "/usr/bin/nmcli", "c", "s")
Expect(err).ToNot(HaveOccurred())
writer.Write([]byte(fmt.Sprintf("\n***** Connection status on node %s *****\n\n %s", node, output)))
writer.Write([]byte(fmt.Sprintf("\n***** Done Connection status on node %s*****\n", node)))

output, err = runAtNode(node, "/usr/bin/nmcli", "d", "s")
Expect(err).ToNot(HaveOccurred())
writer.Write([]byte(fmt.Sprintf("\n***** Device status on node %s ***** \n\n %s", node, output)))
writer.Write([]byte(fmt.Sprintf("\n***** Done device status on node %s *****\n", node)))
output, err = runAtNode(node, "/usr/sbin/ip", "-4", "-o", "a")
Expect(err).ToNot(HaveOccurred())
writer.Write([]byte(fmt.Sprintf("\n***** Configured ipv4 ips on devices on node %s *****\n\n %s", node, output)))
writer.Write([]byte(fmt.Sprintf("\n***** Done ip status on node %s *****\n", node)))
}
writer.Write([]byte(fmt.Sprintf("\n***** Finished printing device status *****\n\n")))
})
}

// Cleanup cleans up the current content of the artifactsDir
func (r *KubernetesNMStateReporter) Cleanup() {
// clean up artifacts from previous run
if r.artifactsDir != "" {
names, err := ioutil.ReadDir(r.artifactsDir)
if err != nil {
panic(err)
}
for _, entery := range names {
os.RemoveAll(path.Join([]string{r.artifactsDir, entery.Name()}...))
}
}
}

func (r *KubernetesNMStateReporter) logNetworkManager(testName string, sinceTime time.Time) {
r.OpenTestLogFile("NetworkManager", testName, func(writer io.ReadWriteCloser) {
for _, node := range nodes {
output, err := runAtNode(node, "sudo", "journalctl", "-u", "NetworkManager",
"--since", fmt.Sprintf("'%ds ago'", 10+int(time.Now().Sub(sinceTime).Seconds())))
Expect(err).ToNot(HaveOccurred())
writer.Write([]byte(fmt.Sprintf("\n***** Journalctl for NetworkManager on node %s *****\n\n %s", node, output)))
writer.Write([]byte(fmt.Sprintf("\n***** Done NetworkManager logs on node %s *****\n", node)))
}
})
}

func (r *KubernetesNMStateReporter) logPods(testName string, namespace string, sinceTime time.Time) error {
if framework.Global.LocalOperator {
return nil
}
r.OpenTestLogFile("pods", testName, func(writer io.ReadWriteCloser) {
podLogOpts := corev1.PodLogOptions{}
podLogOpts.SinceTime = &metav1.Time{sinceTime}
podList := &corev1.PodList{}
err := framework.Global.Client.List(context.TODO(), podList, &dynclient.ListOptions{})
Expect(err).ToNot(HaveOccurred())
podsClientset := framework.Global.KubeClient.CoreV1().Pods(namespace)

for _, pod := range podList.Items {
appLabel, hasAppLabel := pod.Labels["app"]
if !hasAppLabel || appLabel != "kubernetes-nmstate" {
continue
}
req := podsClientset.GetLogs(pod.Name, &podLogOpts)
podLogs, err := req.Stream()
if err != nil {
io.WriteString(GinkgoWriter, fmt.Sprintf("error in opening stream: %v\n", err))
continue
}
defer podLogs.Close()
rawLogs, err := ioutil.ReadAll(podLogs)
if err != nil {
io.WriteString(GinkgoWriter, fmt.Sprintf("error reading kubernetes-nmstate logs: %v\n", err))
continue
}
formattedLogs := strings.Replace(string(rawLogs), "\\n", "\n", -1)
io.WriteString(writer, formattedLogs)
}
})
return nil
}

func (r *KubernetesNMStateReporter) OpenTestLogFile(logType string, testName string, cb func(f io.ReadWriteCloser)) {
name := fmt.Sprintf("%s/%s_%s.log", r.artifactsDir, testName, logType)
fi, err := os.OpenFile(name, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0644)
if err != nil {
fmt.Println(err)
return
}
defer func() {
if err := fi.Close(); err != nil {
fmt.Println(err)
return
}
}()
cb(fi)
}
45 changes: 7 additions & 38 deletions test/e2e/utils.go
Original file line number Diff line number Diff line change
Expand Up @@ -5,9 +5,8 @@ import (
"context"
"fmt"
"github.com/nmstate/kubernetes-nmstate/build/_output/bin/go/src/encoding/json"
"io"
"io/ioutil"
"os/exec"
"path"
"strconv"
"strings"
"testing"
Expand All @@ -18,7 +17,6 @@ import (

"github.com/tidwall/gjson"

corev1 "k8s.io/api/core/v1"
apierrors "k8s.io/apimachinery/pkg/api/errors"
metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
"k8s.io/apimachinery/pkg/types"
Expand All @@ -41,41 +39,6 @@ var (
bondConunter = 0
)

func writePodsLogs(namespace string, sinceTime time.Time, writer io.Writer) error {
if framework.Global.LocalOperator {
return nil
}

podLogOpts := corev1.PodLogOptions{}
podLogOpts.SinceTime = &metav1.Time{sinceTime}
podList := &corev1.PodList{}
err := framework.Global.Client.List(context.TODO(), podList, &dynclient.ListOptions{})
Expect(err).ToNot(HaveOccurred())
podsClientset := framework.Global.KubeClient.CoreV1().Pods(namespace)

for _, pod := range podList.Items {
appLabel, hasAppLabel := pod.Labels["app"]
if !hasAppLabel || appLabel != "kubernetes-nmstate" {
continue
}
req := podsClientset.GetLogs(pod.Name, &podLogOpts)
podLogs, err := req.Stream()
if err != nil {
io.WriteString(writer, fmt.Sprintf("error in opening stream: %v\n", err))
continue
}
defer podLogs.Close()
rawLogs, err := ioutil.ReadAll(podLogs)
if err != nil {
io.WriteString(writer, fmt.Sprintf("error reading kubernetes-nmstate logs: %v\n", err))
continue
}
formattedLogs := strings.Replace(string(rawLogs), "\\n", "\n", -1)
io.WriteString(writer, formattedLogs)
}
return nil
}

func interfacesName(interfaces []interface{}) []string {
var names []string
for _, iface := range interfaces {
Expand Down Expand Up @@ -578,7 +541,13 @@ func defaultRouteNextHopInterface(node string) AsyncAssertion {
return gjson.ParseBytes(currentStateJSON(node)).Get(path).String()
}, 15*time.Second, 1*time.Second)
}

func vlan(node string, iface string) string {
vlanFilter := fmt.Sprintf("interfaces.#(name==\"%s\").vlan.id", iface)
return gjson.ParseBytes(currentStateJSON(node)).Get(vlanFilter).String()
}

func getTestName() string {
fileName := path.Base(CurrentGinkgoTestDescription().FileName)
return strings.TrimSuffix(fileName, ".go")
}

0 comments on commit c23b1e2

Please sign in to comment.