Skip to content

Commit

Permalink
Improves logging by:
Browse files Browse the repository at this point in the history 
- capitalizing log messages,
- adding additional logging for user logins (session creation), and
- reducing the log level of these spammy grpc `info` lines to `debug`.
  • Loading branch information
@nwaldispuehl
nwaldispuehl committed Jul 2, 2023
1 parent f0fd9ca commit 5b1710a
Show file tree
Hide file tree
Showing 15 changed files with 120 additions and 95 deletions.
44 changes: 22 additions & 22 deletions cmd/serve/main.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -87,7 +87,7 @@ func (cmd *servecmd) Run() {
logrus.Fatal(err)
}
if !vpnip.IsValid() && !vpnipv6.IsValid() {
logrus.Fatal("need at least one of VPN.CIDR or VPN.CIDRv6 set")
logrus.Fatal("Need at least one of VPN.CIDR or VPN.CIDRv6 set")
}

// Allow traffic to wg-access-server's peer endpoint.
Expand Down Expand Up @@ -119,12 +119,12 @@ func (cmd *servecmd) Run() {
}
wgimpl, err := wgembed.NewWithOpts(wgOpts)
if err != nil {
logrus.Fatal(errors.Wrap(err, "failed to create wireguard interface"))
logrus.Fatal(errors.Wrap(err, "Failed to create WireGuard interface"))
}
defer wgimpl.Close()
wg = wgimpl

logrus.Infof("starting wireguard server on :%d", conf.WireGuard.Port)
logrus.Infof("Starting WireGuard server on :%d", conf.WireGuard.Port)

wgconfig := &wgembed.ConfigFile{
Interface: wgembed.IfaceConfig{
Expand All @@ -135,11 +135,11 @@ func (cmd *servecmd) Run() {
}

if err := wg.LoadConfig(wgconfig); err != nil {
logrus.Error(errors.Wrap(err, "failed to load wireguard config"))
logrus.Error(errors.Wrap(err, "Failed to load WireGuard config"))
return
}

logrus.Infof("wireguard VPN network is %s", network.StringJoinIPNets(vpnip, vpnipv6))
logrus.Infof("WireGuard VPN network is %s", network.StringJoinIPNets(vpnip, vpnipv6))

options := network.ForwardingOptions{
GatewayIface: conf.VPN.GatewayInterface,
Expand All @@ -160,11 +160,11 @@ func (cmd *servecmd) Run() {
// Storage
storageBackend, err := storage.NewStorage(conf.Storage)
if err != nil {
logrus.Error(errors.Wrap(err, "failed to create storage backend"))
logrus.Error(errors.Wrap(err, "Failed to create storage backend"))
return
}
if err := storageBackend.Open(); err != nil {
logrus.Error(errors.Wrap(err, "failed to connect/open storage backend"))
logrus.Error(errors.Wrap(err, "Failed to connect/open storage backend"))
return
}
defer storageBackend.Close()
Expand All @@ -187,7 +187,7 @@ func (cmd *servecmd) Run() {
ListenAddr: listenAddr,
})
if err != nil {
logrus.Error(errors.Wrap(err, "failed to create dns server"))
logrus.Error(errors.Wrap(err, "Failed to create dns server"))
return
}
dns.ListenAndServe()
Expand All @@ -214,7 +214,7 @@ func (cmd *servecmd) Run() {

// Services
if err := deviceManager.StartSync(conf.DisableMetadata, conf.EnableInactiveDeviceDeletion, conf.InactiveDeviceGracePeriod); err != nil {
logrus.Error(errors.Wrap(err, "failed to sync"))
logrus.Error(errors.Wrap(err, "Failed to sync"))
return
}

Expand All @@ -228,7 +228,7 @@ func (cmd *servecmd) Run() {
// Authentication middleware
middleware, err := authnz.NewMiddleware(conf.Auth, authnz.ClaimsMiddleware(conf))
if err != nil {
logrus.Error(errors.Wrap(err, "failed to set up authnz middleware"))
logrus.Error(errors.Wrap(err, "Failed to set up authnz middleware"))
return
}
router.Use(middleware)
Expand Down Expand Up @@ -262,10 +262,10 @@ func (cmd *servecmd) Run() {

go func() {
// Start Web server
logrus.Infof("web ui listening on %v", address)
logrus.Infof("Web UI listening on %v", address)
err := srv.ListenAndServe()
if err != nil && !errors.Is(err, http.ErrServerClosed) {
errChan <- errors.Wrap(err, "unable to start http server")
errChan <- errors.Wrap(err, "Unable to start http server")
}
}()

Expand All @@ -289,7 +289,7 @@ func (cmd *servecmd) ReadConfig() *config.AppConfig {
if cmd.ConfigFilePath != "" {
if b, err := ioutil.ReadFile(cmd.ConfigFilePath); err == nil {
if err := yaml.Unmarshal(b, &cmd.AppConfig); err != nil {
logrus.Fatal(errors.Wrap(err, "failed to bind configuration file"))
logrus.Fatal(errors.Wrap(err, "Failed to bind configuration file"))
}
}
}
Expand All @@ -306,15 +306,15 @@ func (cmd *servecmd) ReadConfig() *config.AppConfig {

if !cmd.AppConfig.Auth.IsEnabled() {
if cmd.AppConfig.AdminPassword == "" {
logrus.Fatal("missing admin password: please set via environment variable, flag or config file")
logrus.Fatal("Missing admin password: please set via environment variable, flag or config file")
}
}

if cmd.AppConfig.AdminPassword != "" {
// set a basic auth entry for the admin user
pw, err := bcrypt.GenerateFromPassword([]byte(cmd.AppConfig.AdminPassword), bcrypt.DefaultCost)
if err != nil {
logrus.Fatal(errors.Wrap(err, "failed to generate a bcrypt hash for the provided admin password"))
logrus.Fatal(errors.Wrap(err, "Failed to generate a bcrypt hash for the provided admin password"))
}
if cmd.AppConfig.Auth.Simple == nil && cmd.AppConfig.Auth.Basic == nil {
// basic and simple auth are unset, enable simple auth for the admin user
Expand All @@ -337,7 +337,7 @@ func (cmd *servecmd) ReadConfig() *config.AppConfig {
}
key, err := wgtypes.GeneratePrivateKey()
if err != nil {
logrus.Fatal(errors.Wrap(err, "failed to generate a server private key"))
logrus.Fatal(errors.Wrap(err, "Failed to generate a server private key"))
}
cmd.AppConfig.WireGuard.PrivateKey = key.String()
}
Expand Down Expand Up @@ -381,7 +381,7 @@ func detectDNSUpstream(ipv4Enabled, ipv6Enabled bool) []string {
upstream = resolvconf.GetNameservers(r.Content, types.IP)
}
if len(upstream) == 0 {
logrus.Warn("failed to get nameservers from /etc/resolv.conf defaulting to Cloudflare DNS instead")
logrus.Warn("Failed to get nameservers from /etc/resolv.conf defaulting to Cloudflare DNS instead")
// If there's no default route for IPv6, lookup fails immediately without delay and we retry using IPv4
if ipv6Enabled {
upstream = append(upstream, "2606:4700:4700::1111")
Expand All @@ -396,15 +396,15 @@ func detectDNSUpstream(ipv4Enabled, ipv6Enabled bool) []string {
func detectDefaultInterface() string {
links, err := netlink.LinkList()
if err != nil {
logrus.Warn(errors.Wrap(err, "failed to list network interfaces"))
logrus.Warn(errors.Wrap(err, "Failed to list network interfaces"))
return ""
}
for _, link := range links {
// First try IPv4, then IPv6, hope both have the same default interface
for family := range []int{4, 6} {
routes, err := netlink.RouteList(link, family)
if err != nil {
logrus.Warn(errors.Wrapf(err, "failed to list routes for interface %s", link.Attrs().Name))
logrus.Warn(errors.Wrapf(err, "Failed to list routes for interface %s", link.Attrs().Name))
return ""
}
for _, route := range routes {
Expand All @@ -414,14 +414,14 @@ func detectDefaultInterface() string {
}
}
}
logrus.Warn(errors.New("could not determine the default network interface name"))
logrus.Warn(errors.New("Could not determine the default network interface name"))
return ""
}

func generateZone(deviceManager *devices.DeviceManager, vpnips []netip.Addr) dnsproxy.Zone {
devs, err := deviceManager.ListAllDevices()
if err != nil {
logrus.Error(errors.Wrap(err, "could not query devices to generate the DNS zone"))
logrus.Error(errors.Wrap(err, "Could not query devices to generate the DNS zone"))
}

zone := make(dnsproxy.Zone)
Expand All @@ -443,7 +443,7 @@ func generateZone(deviceManager *devices.DeviceManager, vpnips []netip.Addr) dns
return zone
}

var missingPrivateKey = `missing wireguard private key:
var missingPrivateKey = `Missing WireGuard private key:
create a key:
Expand Down
4 changes: 2 additions & 2 deletions internal/config/config.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -24,7 +24,7 @@ type AppConfig struct {
// Defaults to 8000
Port int `yaml:"port"`
// ExternalHost is the address that clients
// use to connect to the wireguard interface
// use to connect to the WireGuard interface
// By default, this will be empty and the web ui
// will use the current page's origin.
ExternalHost string `yaml:"externalHost"`
Expand All @@ -50,7 +50,7 @@ type AppConfig struct {
Filename string `yaml:"filename"`
// Configure WireGuard related settings
WireGuard struct {
// Set this to false to disable the embedded wireguard
// Set this to false to disable the embedded WireGuard
// server. This is useful for development environments
// on mac and windows where we don't currently support
// the OS's network stack.
Expand Down
34 changes: 17 additions & 17 deletions internal/devices/devices.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -38,28 +38,28 @@ func New(wg wgembed.WireGuardInterface, s storage.Storage, cidr, cidrv6 string)
func (d *DeviceManager) StartSync(disableMetadataCollection, enableInactiveDeviceDeletion bool, inactiveDeviceGracePeriod time.Duration) error {
// Start listening to the device add/remove events
d.storage.OnAdd(func(device *storage.Device) {
logrus.Debugf("storage event: device added: %s/%s", device.Owner, device.Name)
logrus.Infof("Storage event: add device '%s' (public key: '%s') for user: %s %s", device.Name, device.PublicKey, device.OwnerName, device.Owner)
if err := d.wg.AddPeer(device.PublicKey, device.PresharedKey, network.SplitAddresses(device.Address)); err != nil {
logrus.Error(errors.Wrap(err, "failed to add wireguard peer"))
logrus.Error(errors.Wrap(err, "Failed to add WireGuard peer"))
}
})

d.storage.OnDelete(func(device *storage.Device) {
logrus.Debugf("storage event: device removed: %s/%s", device.Owner, device.Name)
logrus.Infof("Storage event: remove device '%s' (public key: '%s') for user: %s %s", device.Name, device.PublicKey, device.OwnerName, device.Owner)
if err := d.wg.RemovePeer(device.PublicKey); err != nil {
logrus.Error(errors.Wrap(err, "failed to remove wireguard peer"))
logrus.Error(errors.Wrap(err, "Failed to remove WireGuard peer"))
}
})

d.storage.OnReconnect(func() {
if err := d.sync(); err != nil {
logrus.Error(errors.Wrap(err, "device sync after storage backend reconnect event failed"))
logrus.Error(errors.Wrap(err, "Device sync after storage backend reconnect event failed"))
}
})

// Do an initial sync of existing devices
if err := d.sync(); err != nil {
return errors.Wrap(err, "initial device sync from storage failed")
return errors.Wrap(err, "Initial device sync from storage failed")
}

// start the metrics loop
Expand Down Expand Up @@ -89,7 +89,7 @@ func (d *DeviceManager) AddDevice(identity *authsession.Identity, name string, p
var nameTaken bool = false
devices, err := d.ListDevices(identity.Subject)
if err != nil {
return nil, errors.Wrap(err, "failed to list devices")
return nil, errors.Wrap(err, "Failed to list devices")
}

for _, x := range devices {
Expand Down Expand Up @@ -130,7 +130,7 @@ func (d *DeviceManager) AddDevice(identity *authsession.Identity, name string, p
}

if err := d.SaveDevice(device); err != nil {
return nil, errors.Wrap(err, "failed to save the new device")
return nil, errors.Wrap(err, "Failed to save the new device")
}

return device, nil
Expand All @@ -143,27 +143,27 @@ func (d *DeviceManager) SaveDevice(device *storage.Device) error {
func (d *DeviceManager) sync() error {
devices, err := d.ListAllDevices()
if err != nil {
return errors.Wrap(err, "failed to list devices")
return errors.Wrap(err, "Failed to list devices")
}

peers, err := d.wg.ListPeers()
if err != nil {
return errors.Wrap(err, "failed to list peers")
return errors.Wrap(err, "Failed to list peers")
}

// Remove any peers for devices that are no longer in storage
for _, peer := range peers {
if !deviceListContains(devices, peer.PublicKey.String()) {
if err := d.wg.RemovePeer(peer.PublicKey.String()); err != nil {
logrus.Error(errors.Wrapf(err, "failed to remove peer during sync: %s", peer.PublicKey.String()))
logrus.Error(errors.Wrapf(err, "Failed to remove peer during sync: %s", peer.PublicKey.String()))
}
}
}

// Add peers for all devices in storage
for _, device := range devices {
if err := d.wg.AddPeer(device.PublicKey, device.PresharedKey, network.SplitAddresses(device.Address)); err != nil {
logrus.Warn(errors.Wrapf(err, "failed to add device during sync: %s", device.Name))
logrus.Warn(errors.Wrapf(err, "Failed to add device during sync: %s", device.Name))
}
}

Expand Down Expand Up @@ -291,7 +291,7 @@ func deviceListContains(devices []*storage.Device, publicKey string) bool {
func (d *DeviceManager) ListUsers() ([]*User, error) {
devices, err := d.storage.List("")
if err != nil {
return nil, errors.Wrap(err, "failed to retrieve devices")
return nil, errors.Wrap(err, "Failed to retrieve devices")
}

seen := map[string]bool{}
Expand All @@ -309,13 +309,13 @@ func (d *DeviceManager) ListUsers() ([]*User, error) {
func (d *DeviceManager) DeleteDevicesForUser(user string) error {
devices, err := d.ListDevices(user)
if err != nil {
return errors.Wrap(err, "failed to retrieve devices")
return errors.Wrap(err, "Failed to retrieve devices")
}

for _, dev := range devices {
// TODO not transactional
if err := d.DeleteDevice(user, dev.Name); err != nil {
return errors.Wrap(err, "failed to delete device")
return errors.Wrap(err, "Failed to delete device")
}
}

Expand All @@ -324,11 +324,11 @@ func (d *DeviceManager) DeleteDevicesForUser(user string) error {

func (d *DeviceManager) Ping() error {
if err := d.storage.Ping(); err != nil {
return errors.Wrap(err, "failed to ping storage")
return errors.Wrap(err, "Failed to ping storage")
}

if err := d.wg.Ping(); err != nil {
return errors.Wrap(err, "failed to ping wireguard")
return errors.Wrap(err, "Failed to ping WireGuard")
}

return nil
Expand Down
10 changes: 5 additions & 5 deletions internal/devices/inactive.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -16,16 +16,16 @@ func inactiveLoop(d *DeviceManager, inactiveDeviceGracePeriod time.Duration) {
}

func checkAndRemove(d *DeviceManager, inactiveDeviceGracePeriod time.Duration) {
logrus.Debug("inactive check executing")
logrus.Debug("Inactive check executing")

devices, err := d.ListAllDevices()
if err != nil {
logrus.Warn(errors.Wrap(err, "failed to list devices - inactive devices cannot be deleted"))
logrus.Warn(errors.Wrap(err, "Failed to list devices - inactive devices cannot be deleted"))
return
}

for _, dev := range devices {
logrus.Debugf("checking inactive device: %s/%s", dev.Owner, dev.Name)
logrus.Debugf("Checking inactive device: %s/%s", dev.Owner, dev.Name)

var elapsed time.Duration
if dev.LastHandshakeTime == nil {
Expand All @@ -36,10 +36,10 @@ func checkAndRemove(d *DeviceManager, inactiveDeviceGracePeriod time.Duration) {
}

if elapsed > inactiveDeviceGracePeriod {
logrus.Warnf("deleting inactive device: %s/%s", dev.Owner, dev.Name)
logrus.Warnf("Deleting inactive device: %s/%s", dev.Owner, dev.Name)
err := d.DeleteDevice(dev.Owner, dev.Name)
if err != nil {
logrus.Error(errors.Wrap(err, fmt.Sprintf("failed to delete device: %s/%s", dev.Owner, dev.Name)))
logrus.Error(errors.Wrap(err, fmt.Sprintf("Failed to delete device: %s/%s", dev.Owner, dev.Name)))
continue
}
}
Expand Down
6 changes: 3 additions & 3 deletions internal/devices/metadata.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -15,11 +15,11 @@ func metadataLoop(d *DeviceManager) {
}

func syncMetrics(d *DeviceManager) {
logrus.Debug("metadata sync executing")
logrus.Debug("Metadata sync executing")

peers, err := d.wg.ListPeers()
if err != nil {
logrus.Warn(errors.Wrap(err, "failed to list peers - metrics cannot be recorded"))
logrus.Warn(errors.Wrap(err, "Failed to list peers - metrics cannot be recorded"))
return
}

Expand All @@ -40,7 +40,7 @@ func syncMetrics(d *DeviceManager) {
device.LastHandshakeTime = &peer.LastHandshakeTime

if err := d.SaveDevice(device); err != nil {
logrus.Error(errors.Wrap(err, "failed to save device during metadata sync"))
logrus.Error(errors.Wrap(err, "Failed to save device during metadata sync"))
}
}
}
Expand Down
Loading

0 comments on commit 5b1710a

Please sign in to comment.