From 3413874a359d386b082614637c9ab247bb6510b4 Mon Sep 17 00:00:00 2001 From: Sergey Matveev Date: Sun, 8 May 2016 23:41:41 +0300 Subject: [PATCH] Use RFC 5424-like structured log format --- .../govpn/cmd/govpn-client/main.go | 3 +- .../govpn/cmd/govpn-client/proxy.go | 2 +- .../govpn/cmd/govpn-client/tcp.go | 16 ++++----- .../govpn/cmd/govpn-client/udp.go | 12 +++---- .../govpn/cmd/govpn-server/common.go | 4 +-- .../govpn/cmd/govpn-server/conf.go | 4 +-- .../govpn/cmd/govpn-server/main.go | 18 +++++----- .../govpn/cmd/govpn-server/proxy.go | 9 ++--- .../govpn/cmd/govpn-server/tcp.go | 33 ++++++++++++------- .../govpn/cmd/govpn-server/udp.go | 29 +++++++++++----- src/cypherpunks.ru/govpn/logger.go | 18 +++++++--- 11 files changed, 86 insertions(+), 62 deletions(-) diff --git a/src/cypherpunks.ru/govpn/cmd/govpn-client/main.go b/src/cypherpunks.ru/govpn/cmd/govpn-client/main.go index c2ddb3e..38bdae3 100644 --- a/src/cypherpunks.ru/govpn/cmd/govpn-client/main.go +++ b/src/cypherpunks.ru/govpn/cmd/govpn-client/main.go @@ -156,8 +156,7 @@ MainCycle: } select { case <-termSignal: - log.Println("Finishing") - govpn.Println("Finishing") + govpn.BothPrintf(`[finish remote="%s"]`, *remoteAddr) termination <- struct{}{} break MainCycle case <-timeouted: diff --git a/src/cypherpunks.ru/govpn/cmd/govpn-client/proxy.go b/src/cypherpunks.ru/govpn/cmd/govpn-client/proxy.go index 430f1ef..0a6729c 100644 --- a/src/cypherpunks.ru/govpn/cmd/govpn-client/proxy.go +++ b/src/cypherpunks.ru/govpn/cmd/govpn-client/proxy.go @@ -52,6 +52,6 @@ func proxyTCP(timeouted, rehandshaking, termination chan struct{}) { if err != nil || resp.StatusCode != http.StatusOK { log.Fatalln("Unexpected response from proxy") } - govpn.Println("Connected to proxy:", *proxyAddr) + govpn.Printf(`[proxy-connected remote="%s" addr="%s"]`, *remoteAddr, *proxyAddr) go handleTCP(conn, timeouted, rehandshaking, termination) } diff --git a/src/cypherpunks.ru/govpn/cmd/govpn-client/tcp.go b/src/cypherpunks.ru/govpn/cmd/govpn-client/tcp.go index 8c232e4..38a8cb5 100644 --- a/src/cypherpunks.ru/govpn/cmd/govpn-client/tcp.go +++ b/src/cypherpunks.ru/govpn/cmd/govpn-client/tcp.go @@ -37,7 +37,7 @@ func startTCP(timeouted, rehandshaking, termination chan struct{}) { if err != nil { log.Fatalln("Can not connect to address:", err) } - govpn.Println("Connected to TCP:" + *remoteAddr) + govpn.Printf(`[connected remote="%s"]`, *remoteAddr) handleTCP(conn, timeouted, rehandshaking, termination) } @@ -57,7 +57,7 @@ HandshakeCycle: default: } if prev == len(buf) { - govpn.Println("Timeouted waiting for the packet") + govpn.Printf(`[packet-timeouted remote="%s"]`, *remoteAddr) timeouted <- struct{}{} break HandshakeCycle } @@ -65,7 +65,7 @@ HandshakeCycle: conn.SetReadDeadline(time.Now().Add(time.Duration(timeout) * time.Second)) n, err = conn.Read(buf[prev:]) if err != nil { - govpn.Println("Connection timeouted") + govpn.Printf(`[connection-timeouted remote="%s"]`, *remoteAddr) timeouted <- struct{}{} break HandshakeCycle } @@ -80,7 +80,7 @@ HandshakeCycle: if peer == nil { continue } - govpn.Println("Handshake completed") + govpn.Printf(`[handshake-completed remote="%s"]`, *remoteAddr) knownPeers = govpn.KnownPeers(map[string]**govpn.Peer{*remoteAddr: &peer}) if firstUpCall { go govpn.ScriptCall(*upPath, *ifaceName, *remoteAddr) @@ -126,14 +126,14 @@ TransportCycle: default: } if prev == len(buf) { - govpn.Println("Timeouted waiting for the packet") + govpn.Printf(`[packet-timeouted remote="%s"]`, *remoteAddr) timeouted <- struct{}{} break TransportCycle } conn.SetReadDeadline(time.Now().Add(time.Duration(timeout) * time.Second)) n, err = conn.Read(buf[prev:]) if err != nil { - govpn.Println("Connection timeouted") + govpn.Printf(`[connection-timeouted remote="%s"]`, *remoteAddr) timeouted <- struct{}{} break TransportCycle } @@ -147,12 +147,12 @@ TransportCycle: continue } if !peer.PktProcess(buf[:i+govpn.NonceSize], tap, false) { - govpn.Println("Unauthenticated packet, dropping connection") + govpn.Printf(`[packet-unauthenticated remote="%s"]`, *remoteAddr) timeouted <- struct{}{} break TransportCycle } if atomic.LoadUint64(&peer.BytesIn)+atomic.LoadUint64(&peer.BytesOut) > govpn.MaxBytesPerKey { - govpn.Println("Need rehandshake") + govpn.Printf(`[rehandshake-required remote="%s"]`, *remoteAddr) rehandshaking <- struct{}{} break TransportCycle } diff --git a/src/cypherpunks.ru/govpn/cmd/govpn-client/udp.go b/src/cypherpunks.ru/govpn/cmd/govpn-client/udp.go index 1b33964..abbbf07 100644 --- a/src/cypherpunks.ru/govpn/cmd/govpn-client/udp.go +++ b/src/cypherpunks.ru/govpn/cmd/govpn-client/udp.go @@ -36,7 +36,7 @@ func startUDP(timeouted, rehandshaking, termination chan struct{}) { if err != nil { log.Fatalln("Can not listen on UDP:", err) } - govpn.Println("Connected to UDP:" + *remoteAddr) + govpn.Printf(`[connected remote="%s"]`, *remoteAddr) hs := govpn.HandshakeStart(*remoteAddr, conn, conf) buf := make([]byte, *mtu*2) @@ -55,7 +55,7 @@ MainCycle: conn.SetReadDeadline(time.Now().Add(time.Second)) n, err = conn.Read(buf) if timeouts == timeout { - govpn.Println("Timeouted") + govpn.Printf(`[connection-timeouted remote="%s"]`, *remoteAddr) timeouted <- struct{}{} break } @@ -67,18 +67,18 @@ MainCycle: if peer.PktProcess(buf[:n], tap, true) { timeouts = 0 } else { - govpn.Println("Unauthenticated packet") + govpn.Printf(`[packet-unauthenticated remote="%s"]`, *remoteAddr) timeouts++ } if atomic.LoadUint64(&peer.BytesIn)+atomic.LoadUint64(&peer.BytesOut) > govpn.MaxBytesPerKey { - govpn.Println("Need rehandshake") + govpn.Printf(`[rehandshake-required remote="%s"]`, *remoteAddr) rehandshaking <- struct{}{} break MainCycle } continue } if idsCache.Find(buf[:n]) == nil { - govpn.Println("Invalid identity in handshake packet") + govpn.Printf(`[identity-invalid remote="%s"]`, *remoteAddr) continue } timeouts = 0 @@ -86,7 +86,7 @@ MainCycle: if peer == nil { continue } - govpn.Println("Handshake completed") + govpn.Printf(`[handshake-completed remote="%s"]`, *remoteAddr) knownPeers = govpn.KnownPeers(map[string]**govpn.Peer{*remoteAddr: &peer}) if firstUpCall { go govpn.ScriptCall(*upPath, *ifaceName, *remoteAddr) diff --git a/src/cypherpunks.ru/govpn/cmd/govpn-server/common.go b/src/cypherpunks.ru/govpn/cmd/govpn-server/common.go index 770ec22..691e51c 100644 --- a/src/cypherpunks.ru/govpn/cmd/govpn-server/common.go +++ b/src/cypherpunks.ru/govpn/cmd/govpn-server/common.go @@ -70,7 +70,7 @@ func callUp(peerId *govpn.PeerId, remoteAddr string) (string, error) { if confs[*peerId].Up != "" { result, err := govpn.ScriptCall(confs[*peerId].Up, ifaceName, remoteAddr) if err != nil { - govpn.Println("Script", confs[*peerId].Up, "call failed", err) + govpn.Printf(`[script-failed bind="%s" path="%s" err="%s"]`, *bindAddr, confs[*peerId].Up, err) return "", err } if ifaceName == "" { @@ -82,7 +82,7 @@ func callUp(peerId *govpn.PeerId, remoteAddr string) (string, error) { } } if ifaceName == "" { - govpn.Println("Can not obtain interface name for", *peerId) + govpn.Printf(`[tap-failed bind="%s" peer="%s"]`, *bindAddr, *peerId) } return ifaceName, nil } diff --git a/src/cypherpunks.ru/govpn/cmd/govpn-server/conf.go b/src/cypherpunks.ru/govpn/cmd/govpn-server/conf.go index 25fddd0..28ee501 100644 --- a/src/cypherpunks.ru/govpn/cmd/govpn-server/conf.go +++ b/src/cypherpunks.ru/govpn/cmd/govpn-server/conf.go @@ -62,7 +62,7 @@ func confRead() (*map[govpn.PeerId]*govpn.PeerConf, error) { pc.MTU = govpn.MTUDefault } if pc.MTU > govpn.MTUMax { - govpn.Println("MTU value", pc.MTU, "is too high, overriding to", govpn.MTUMax) + govpn.Printf(`[mtu-high bind="%s" value="%d" overriden="%d"]`, *bindAddr, pc.MTU, govpn.MTUMax) pc.MTU = govpn.MTUMax } conf := govpn.PeerConf{ @@ -90,7 +90,7 @@ func confRead() (*map[govpn.PeerId]*govpn.PeerConf, error) { func confRefresh() error { newConfs, err := confRead() if err != nil { - govpn.Println("Unable to parse peers configuration:", err) + govpn.Printf(`[conf-parse-failed bind="%s" err="%s"]`, *bindAddr, err) return err } confs = *newConfs diff --git a/src/cypherpunks.ru/govpn/cmd/govpn-server/main.go b/src/cypherpunks.ru/govpn/cmd/govpn-server/main.go index 4b42065..c70e82a 100644 --- a/src/cypherpunks.ru/govpn/cmd/govpn-server/main.go +++ b/src/cypherpunks.ru/govpn/cmd/govpn-server/main.go @@ -60,6 +60,10 @@ func main() { govpn.EGDInit(*egdPath) } + if *syslog { + govpn.SyslogEnable() + } + switch *proto { case "udp": startUDP() @@ -89,20 +93,14 @@ func main() { if *proxy != "" { go proxyStart() } - - if *syslog { - govpn.SyslogEnable() - } - log.Println("Server started") - govpn.Println("Server started") + govpn.BothPrintf(`[started bind="%s"]`, *bindAddr) var needsDeletion bool MainCycle: for { select { case <-termSignal: - log.Println("Terminating") - govpn.Println("Terminating") + govpn.BothPrintf(`[terminating bind="%s"]`, *bindAddr) for _, ps := range peers { govpn.ScriptCall( confs[*ps.peer.Id].Down, @@ -116,7 +114,7 @@ MainCycle: hsLock.Lock() for addr, hs := range handshakes { if hs.LastPing.Add(timeout).Before(now) { - govpn.Println("Deleting handshake state", addr) + govpn.Printf(`[handshake-delete bind="%s" addr="%s"]`, *bindAddr, addr) hs.Zero() delete(handshakes, addr) } @@ -129,7 +127,7 @@ MainCycle: needsDeletion = ps.peer.LastPing.Add(timeout).Before(now) ps.peer.BusyR.Unlock() if needsDeletion { - govpn.Println("Deleting peer", ps.peer) + govpn.Printf(`[peer-delete bind="%s" peer="%s"]`, *bindAddr, ps.peer) delete(peers, addr) delete(knownPeers, addr) delete(peersById, *ps.peer.Id) diff --git a/src/cypherpunks.ru/govpn/cmd/govpn-server/proxy.go b/src/cypherpunks.ru/govpn/cmd/govpn-server/proxy.go index bcfd882..02c1f0f 100644 --- a/src/cypherpunks.ru/govpn/cmd/govpn-server/proxy.go +++ b/src/cypherpunks.ru/govpn/cmd/govpn-server/proxy.go @@ -19,7 +19,6 @@ along with this program. If not, see . package main import ( - "log" "net/http" "cypherpunks.ru/govpn" @@ -30,7 +29,7 @@ type proxyHandler struct{} func (p proxyHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { conn, _, err := w.(http.Hijacker).Hijack() if err != nil { - govpn.Println("Hijacking failed:", err.Error()) + govpn.Printf(`[proxy-hijack-failed bind="%s" err="%s"]`, *bindAddr, err) return } conn.Write([]byte("HTTP/1.0 200 OK\n\n")) @@ -38,12 +37,10 @@ func (p proxyHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { } func proxyStart() { - log.Println("HTTP proxy listening on:" + *proxy) - govpn.Println("HTTP proxy listening on:" + *proxy) + govpn.BothPrintf(`[proxy-listen bind="%s" addr="%s"]`, *bindAddr, *proxy) s := &http.Server{ Addr: *proxy, Handler: proxyHandler{}, } - log.Println("HTTP proxy result:", s.ListenAndServe()) - govpn.Println("HTTP proxy result:", s.ListenAndServe()) + govpn.BothPrintf(`[proxy-finished bind="%s" result="%s"]`, *bindAddr, s.ListenAndServe()) } diff --git a/src/cypherpunks.ru/govpn/cmd/govpn-server/tcp.go b/src/cypherpunks.ru/govpn/cmd/govpn-server/tcp.go index f8a76e2..66b9345 100644 --- a/src/cypherpunks.ru/govpn/cmd/govpn-server/tcp.go +++ b/src/cypherpunks.ru/govpn/cmd/govpn-server/tcp.go @@ -36,13 +36,12 @@ func startTCP() { if err != nil { log.Fatalln("Can not listen on TCP:", err) } - log.Println("Listening on TCP:" + *bindAddr) - govpn.Println("Listening on TCP:" + *bindAddr) + govpn.BothPrintf(`[tcp-listen bind="%s"]`, *bindAddr) go func() { for { conn, err := listener.AcceptTCP() if err != nil { - govpn.Println("Error accepting TCP:", err) + govpn.Printf(`[tcp-accept-failed bind="%s" err="%s"]`, *bindAddr, err) continue } go handleTCP(conn) @@ -79,7 +78,10 @@ func handleTCP(conn net.Conn) { if hs == nil { conf = confs[*peerId] if conf == nil { - govpn.Println("Can not get peer configuration:", peerId.String()) + govpn.Printf( + `[conf-get-failed bind="%s" peer="%s"]`, + *bindAddr, peerId.String(), + ) break } hs = govpn.NewHandshake(addr, conn, conf) @@ -90,7 +92,10 @@ func handleTCP(conn net.Conn) { continue } hs.Zero() - govpn.Println("Peer handshake finished:", addr, peer.Id.String()) + govpn.Printf( + `[handshake-completed bind="%s" addr="%s" peer="%s"]`, + *bindAddr, addr, peerId.String(), + ) peersByIdLock.RLock() addrPrev, exists := peersById[*peer.Id] peersByIdLock.RUnlock() @@ -114,7 +119,10 @@ func handleTCP(conn net.Conn) { peersLock.Unlock() peersByIdLock.Unlock() kpLock.Unlock() - govpn.Println("Rehandshake processed:", peer.Id.String()) + govpn.Printf( + `[rehandshake-completed bind="%s" peer="%s"]`, + *bindAddr, peerId.String(), + ) } else { ifaceName, err := callUp(peer.Id, peer.Addr) if err != nil { @@ -123,7 +131,10 @@ func handleTCP(conn net.Conn) { } tap, err = govpn.TAPListen(ifaceName, peer.MTU) if err != nil { - govpn.Println("Unable to create TAP:", err) + govpn.Printf( + `[tap-failed bind="%s" peer="%s" err="%s"]`, + *bindAddr, peerId.String(), err, + ) peer = nil break } @@ -142,7 +153,7 @@ func handleTCP(conn net.Conn) { peersLock.Unlock() peersByIdLock.Unlock() kpLock.Unlock() - govpn.Println("Peer created:", peer.Id.String()) + govpn.Printf(`[peer-created bind="%s" peer="%s"]`, *bindAddr, peerId.String()) } break } @@ -177,9 +188,9 @@ func handleTCP(conn net.Conn) { continue } if !peer.PktProcess(buf[:i+govpn.NonceSize], tap, false) { - govpn.Println( - "Unauthenticated packet, dropping connection", - addr, peer.Id.String(), + govpn.Printf( + `[packet-unauthenticated bind="%s" addr="%s" peer="%s"]`, + *bindAddr, addr, peer.Id.String(), ) break } diff --git a/src/cypherpunks.ru/govpn/cmd/govpn-server/udp.go b/src/cypherpunks.ru/govpn/cmd/govpn-server/udp.go index f654181..374b4dd 100644 --- a/src/cypherpunks.ru/govpn/cmd/govpn-server/udp.go +++ b/src/cypherpunks.ru/govpn/cmd/govpn-server/udp.go @@ -48,8 +48,7 @@ func startUDP() { if err != nil { log.Fatalln("Can not listen on UDP:", err) } - log.Println("Listening on UDP:" + *bindAddr) - govpn.Println("Listening on UDP:" + *bindAddr) + govpn.BothPrintf(`[udp-listen bind="%s"]`, *bindAddr) udpBufs <- make([]byte, govpn.MTUMax) go func() { @@ -69,7 +68,7 @@ func startUDP() { buf = <-udpBufs n, raddr, err = conn.ReadFromUDP(buf) if err != nil { - govpn.Println("Unexpected error when receiving", err) + govpn.Printf(`[receive-failed bind="%s" err="%s"]`, *bindAddr, err) break } addr = raddr.String() @@ -97,7 +96,10 @@ func startUDP() { goto Finished } - govpn.Println("Peer handshake finished:", addr, peer.Id.String()) + govpn.Printf( + `[handshake-completed bind="%s" addr="%s" peer="%s"]`, + *bindAddr, addr, peerId.String(), + ) hs.Zero() hsLock.Lock() delete(handshakes, addr) @@ -133,7 +135,10 @@ func startUDP() { peersLock.Unlock() peersByIdLock.Unlock() kpLock.Unlock() - govpn.Println("Rehandshake processed:", peer.Id.String()) + govpn.Printf( + `[rehandshake-completed bind="%s" peer="%s"]`, + *bindAddr, peer.Id.String(), + ) } else { go func(addr string, peer *govpn.Peer) { ifaceName, err := callUp(peer.Id, peer.Addr) @@ -142,7 +147,10 @@ func startUDP() { } tap, err := govpn.TAPListen(ifaceName, peer.MTU) if err != nil { - govpn.Println("Unable to create TAP:", err) + govpn.Printf( + `[tap-failed bind="%s" peer="%s" err="%s"]`, + *bindAddr, peer.Id.String(), err, + ) return } ps = &PeerState{ @@ -164,19 +172,22 @@ func startUDP() { peersLock.Unlock() peersByIdLock.Unlock() kpLock.Unlock() - govpn.Println("Peer created:", peer.Id.String()) + govpn.Printf(`[peer-created bind="%s" peer="%s"]`, *bindAddr, peer.Id.String()) }(addr, peer) } goto Finished CheckID: peerId = idsCache.Find(buf[:n]) if peerId == nil { - govpn.Println("Unknown identity from:", addr) + govpn.Printf(`[identity-unknown bind="%s" addr="%s"]`, *bindAddr, addr) goto Finished } conf = confs[*peerId] if conf == nil { - govpn.Println("Unable to get peer configuration:", peerId.String()) + govpn.Printf( + `[conf-get-failed bind="%s" peer="%s"]`, + *bindAddr, peerId.String(), + ) goto Finished } hs = govpn.NewHandshake( diff --git a/src/cypherpunks.ru/govpn/logger.go b/src/cypherpunks.ru/govpn/logger.go index f646338..b110ce3 100644 --- a/src/cypherpunks.ru/govpn/logger.go +++ b/src/cypherpunks.ru/govpn/logger.go @@ -36,12 +36,20 @@ func SyslogEnable() { } } -// Call either syslog-related logger.Println if SyslogEnabled, -// default log.Println otherwise. -func Println(v ...interface{}) { +// Call either syslog-related logger.Printf if SyslogEnabled, +// default log.Printf otherwise. +func Printf(f string, v ...interface{}) { if sysloger == nil { - log.Println(v...) + log.Printf(f, v...) } else { - sysloger.Println(v...) + sysloger.Printf(f, v...) + } +} + +// Call both default log.Printf and syslog-related one. +func BothPrintf(f string, v ...interface{}) { + log.Printf(f, v...) + if sysloger != nil { + sysloger.Printf(f, v...) } } -- 2.44.0