Fix race conditions, add pprof and trace logging args (#6)

.gitignore

@@ -1 +1 @@
-/bin
+/qemu-vmnet

go.mod

@@ -1,7 +1,14 @@
 module github.com/adnsio/qemu-vmnet
 
-go 1.17
+go 1.18
 
-require github.com/google/gopacket v1.1.19
+require (
+	github.com/google/gopacket v1.1.19
+	github.com/rs/zerolog v1.27.0
+)
 
-require github.com/rs/zerolog v1.26.1 // indirect
+require (
+	github.com/mattn/go-colorable v0.1.12 // indirect
+	github.com/mattn/go-isatty v0.0.14 // indirect
+	golang.org/x/sys v0.0.0-20210927094055-39ccf1dd6fa6 // indirect
+)

go.sum

@@ -1,37 +1,27 @@
-github.com/coreos/go-systemd/v22 v22.3.2/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc=
+github.com/coreos/go-systemd/v22 v22.3.3-0.20220203105225-a9a7ef127534/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc=
 github.com/godbus/dbus/v5 v5.0.4/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5xrFpKfA=
 github.com/google/gopacket v1.1.19 h1:ves8RnFZPGiFnTS0uPQStjwru6uO6h+nlr9j6fL7kF8=
 github.com/google/gopacket v1.1.19/go.mod h1:iJ8V8n6KS+z2U1A8pUwu8bW5SyEMkXJB8Yo/Vo+TKTo=
+github.com/mattn/go-colorable v0.1.12 h1:jF+Du6AlPIjs2BiUiQlKOX0rt3SujHxPnksPKZbaA40=
+github.com/mattn/go-colorable v0.1.12/go.mod h1:u5H1YNBxpqRaxsYJYSkiCWKzEfiAb1Gb520KVy5xxl4=
+github.com/mattn/go-isatty v0.0.14 h1:yVuAays6BHfxijgZPzw+3Zlu5yQgKGP2/hcQbHb7S9Y=
+github.com/mattn/go-isatty v0.0.14/go.mod h1:7GGIvUiUoEMVVmxf/4nioHXj79iQHKdU27kJ6hsGG94=
 github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
 github.com/rs/xid v1.3.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg=
-github.com/rs/zerolog v1.26.1 h1:/ihwxqH+4z8UxyI70wM1z9yCvkWcfz/a3mj48k/Zngc=
-github.com/rs/zerolog v1.26.1/go.mod h1:/wSSJWX7lVrsOwlbyTRSOJvqRlc+WjWlfes+CiJ+tmc=
-github.com/yuin/goldmark v1.4.0/go.mod h1:mwnBkeHKe2W/ZEtQ+71ViKU8L12m81fl3OWwC1Zlc8k=
+github.com/rs/zerolog v1.27.0 h1:1T7qCieN22GVc8S4Q2yuexzBb1EqjbgjSH9RohbMjKs=
+github.com/rs/zerolog v1.27.0/go.mod h1:7frBqO0oezxmnO7GF86FY++uy8I0Tk/If5ni1G9Qc0U=
 golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w=
 golang.org/x/crypto v0.0.0-20191011191535-87dc89f01550/go.mod h1:yigFU9vqHzYiE8UmvKecakEJjdnWj3jj499lnFckfCI=
-golang.org/x/crypto v0.0.0-20211215165025-cf75a172585e/go.mod h1:P+XmwS30IXTQdn5tA2iutPOUgjI07+tq3H3K9MVA1s8=
 golang.org/x/lint v0.0.0-20200302205851-738671d3881b/go.mod h1:3xt1FjdF8hUf6vQPIChWIBhFzV8gjjsPE/fR3IyQdNY=
 golang.org/x/mod v0.1.1-0.20191105210325-c90efee705ee/go.mod h1:QqPTAvyqsEbceGzBzNggFXnrqF1CaUcvgkdR5Ot7KZg=
-golang.org/x/mod v0.4.2/go.mod h1:s0Qsj1ACt9ePp/hMypM3fl4fZqREWJwdYDEqhRiZZUA=
 golang.org/x/net v0.0.0-20190404232315-eb5bcb51f2a3/go.mod h1:t9HGtf8HONx5eT2rtn7q6eTqICYqUVnKs3thJo3Qplg=
 golang.org/x/net v0.0.0-20190620200207-3b0461eec859/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s=
-golang.org/x/net v0.0.0-20210226172049-e18ecbb05110/go.mod h1:m0MpNAwzfU5UDzcl9v0D8zg8gWTRqZa9RBIspLL5mdg=
-golang.org/x/net v0.0.0-20210805182204-aaa1db679c0d/go.mod h1:9nx3DQGgdP8bBQD5qxJ1jj9UTztislL4KSBs9R2vV5Y=
 golang.org/x/sync v0.0.0-20190423024810-112230192c58/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
-golang.org/x/sync v0.0.0-20210220032951-036812b2e83c/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
 golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
 golang.org/x/sys v0.0.0-20190412213103-97732733099d/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
-golang.org/x/sys v0.0.0-20201119102817-f84b799fce68/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
-golang.org/x/sys v0.0.0-20210423082822-04245dca01da/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
-golang.org/x/sys v0.0.0-20210809222454-d867a43fc93e/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
-golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo=
+golang.org/x/sys v0.0.0-20210630005230-0f9fa26af87c/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.0.0-20210927094055-39ccf1dd6fa6 h1:foEbQz/B0Oz6YIqu/69kfXPYeFQAuuMYFkjaqXzl5Wo=
+golang.org/x/sys v0.0.0-20210927094055-39ccf1dd6fa6/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=
-golang.org/x/text v0.3.3/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ=
-golang.org/x/text v0.3.6/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ=
-golang.org/x/tools v0.0.0-20180917221912-90fa682c2a6e/go.mod h1:n7NCudcB/nEzxVGmLbDWY5pfWTLqBcC2KZ6jyYvM4mQ=
-golang.org/x/tools v0.0.0-20191119224855-298f0cb1881e/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo=
 golang.org/x/tools v0.0.0-20200130002326-2f3ba24bd6e7/go.mod h1:TB2adYChydJhpapKDTa4BR/hXlZSLoq2Wpct/0txZ28=
-golang.org/x/tools v0.1.7/go.mod h1:LGqMHiF4EqQNHR1JncWGqT5BVaXmza+X+BDGol+dOxo=
-golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
 golang.org/x/xerrors v0.0.0-20191011141410-1b5146add898/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
-golang.org/x/xerrors v0.0.0-20200804184101-5ec99f83aff1/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=

main.go

@@ -6,6 +6,9 @@ import (
 	"net"
 	"os"
 	"os/signal"
+	"runtime"
+	"runtime/pprof"
+	"sync"
 	"syscall"
 
 	"github.com/adnsio/qemu-vmnet/pkg/vmnet"
@@ -19,14 +22,35 @@ func main() {
 	log.Logger = log.Output(zerolog.ConsoleWriter{Out: os.Stderr})
 
 	debug := flag.Bool("debug", false, "sets log level to debug")
+	trace := flag.Bool("trace", false, "sets log level to trace")
 	address := flag.String("address", ":2233", "sets the listening address")
+	cpuprofile := flag.String("cpuprofile", "", "write cpu profile to `file`")
+	memprofile := flag.String("memprofile", "", "write memory profile to `file`")
 
 	flag.Parse()
 
+	if *cpuprofile != "" {
+		f, err := os.Create(*cpuprofile)
+		if err != nil {
+			log.Fatal().Msgf("could not create CPU profile: %s", err.Error())
+			return
+		}
+		defer f.Close()
+
+		if err := pprof.StartCPUProfile(f); err != nil {
+			log.Fatal().Msgf("could not start CPU profile: %s", err.Error())
+			return
+		}
+		defer pprof.StopCPUProfile()
+	}
+
 	zerolog.SetGlobalLevel(zerolog.InfoLevel)
 	if *debug {
 		zerolog.SetGlobalLevel(zerolog.DebugLevel)
 	}
+	if *trace {
+		zerolog.SetGlobalLevel(zerolog.TraceLevel)
+	}
 
 	vmn := vmnet.New()
 
@@ -47,6 +71,7 @@ func main() {
 
 	writeToVNNetChan := make(chan []byte)
 	clients := map[string]net.Addr{}
+	clientsMutex := sync.Mutex{}
 
 	go func() {
 		for {
@@ -61,7 +86,8 @@ func main() {
 
 			go func(bytes []byte) {
 				pkt := gopacket.NewPacket(bytes, layers.LayerTypeEthernet, gopacket.Default)
-				log.Debug().Msgf("received %d bytes from vmnet\n%s", len(bytes), pkt.String())
+				log.Debug().Msgf("received %d bytes from vmnet", len(bytes))
+				log.Trace().Msg(pkt.String())
 
 				layer := pkt.Layer(layers.LayerTypeEthernet)
 				if layer == nil {
@@ -71,17 +97,21 @@ func main() {
 				ethLayer, _ := layer.(*layers.Ethernet)
 				destinationMAC := ethLayer.DstMAC.String()
 
+				clientsMutex.Lock()
 				addr, exist := clients[destinationMAC]
+				clientsMutex.Unlock()
 				if !exist {
 					return
 				}
 
-				log.Info().Msgf("writing %d bytes to %s", len(bytes), addr.String())
+				log.Debug().Msgf("writing %d bytes to %s", len(bytes), destinationMAC)
 
 				if _, err := conn.WriteTo(bytes, addr); err != nil {
 					if errors.Is(err, net.ErrClosed) {
+						// clientsMutex.Lock()
 						delete(clients, destinationMAC)
-						log.Info().Msgf("deleted client with mac %s", destinationMAC)
+						// clientsMutex.Unlock()
+						log.Debug().Msgf("deleted client with mac %s", destinationMAC)
 						return
 					}
 
@@ -96,7 +126,7 @@ func main() {
 		for {
 			bytes := <-writeToVNNetChan
 
-			log.Info().Msgf("writing %d bytes to vmnet", len(bytes))
+			log.Debug().Msgf("writing %d bytes to vmnet", len(bytes))
 
 			if _, err := vmn.Write(bytes); err != nil {
 				log.Error().Msgf("error while writing to vmnet: %s", err.Error())
@@ -122,15 +152,22 @@ func main() {
 
 			go func(bytes []byte) {
 				pkt := gopacket.NewPacket(bytes, layers.LayerTypeEthernet, gopacket.Default)
-				log.Debug().Msgf("received %d bytes from %s\n%s", len(bytes), addr.String(), pkt.String())
 
 				if layer := pkt.Layer(layers.LayerTypeEthernet); layer != nil {
 					eth, _ := layer.(*layers.Ethernet)
+					sourceMAC := eth.SrcMAC.String()
+
+					log.Debug().Msgf("received %d bytes from %s", len(bytes), sourceMAC)
+					log.Trace().Msg(pkt.String())
 
-					_, exist := clients[eth.SrcMAC.String()]
+					clientsMutex.Lock()
+					_, exist := clients[sourceMAC]
+					clientsMutex.Unlock()
 					if !exist {
-						clients[eth.SrcMAC.String()] = addr
-						log.Info().Msgf("new client with mac %s", eth.SrcMAC.String())
+						clientsMutex.Lock()
+						clients[sourceMAC] = addr
+						clientsMutex.Unlock()
+						log.Debug().Msgf("new client with mac %s", sourceMAC)
 					}
 
 					writeToVNNetChan <- bytes
@@ -142,4 +179,20 @@ func main() {
 	sig := make(chan os.Signal, 1)
 	signal.Notify(sig, syscall.SIGINT, syscall.SIGTERM)
 	<-sig
+
+	if *memprofile != "" {
+		f, err := os.Create(*memprofile)
+		if err != nil {
+			log.Fatal().Msgf("could not create memory profile: %s", err.Error())
+			return
+		}
+		defer f.Close()
+
+		runtime.GC()
+
+		if err := pprof.WriteHeapProfile(f); err != nil {
+			log.Fatal().Msgf("could not write memory profile: %s", err.Error())
+			return
+		}
+	}
 }