refactor: proper logging

api/rpc.go

@@ -15,6 +15,7 @@ import (
 type UserService struct{}
 
 func (s *UserService) List(ctx context.Context, req *pb.UserListRequest) (*pb.UserResponse, error) {
+	logrus.Debug("rpc call: user list")
 	var ut []*pb.UserResponse_User
 
 	users, err := ovpm.GetAllUsers()
@@ -35,6 +36,7 @@ func (s *UserService) List(ctx context.Context, req *pb.UserListRequest) (*pb.Us
 }
 
 func (s *UserService) Create(ctx context.Context, req *pb.UserCreateRequest) (*pb.UserResponse, error) {
+	logrus.Debugf("rpc call: user create: %s", req.Username)
 	var ut []*pb.UserResponse_User
 	user, err := ovpm.CreateNewUser(req.Username, req.Password)
 	if err != nil {
@@ -51,6 +53,7 @@ func (s *UserService) Create(ctx context.Context, req *pb.UserCreateRequest) (*p
 }
 
 func (s *UserService) Delete(ctx context.Context, req *pb.UserDeleteRequest) (*pb.UserResponse, error) {
+	logrus.Debugf("rpc call: user delete: %s", req.Username)
 	var ut []*pb.UserResponse_User
 	user, err := ovpm.GetUser(req.Username)
 	if err != nil {
@@ -72,6 +75,7 @@ func (s *UserService) Delete(ctx context.Context, req *pb.UserDeleteRequest) (*p
 }
 
 func (s *UserService) Renew(ctx context.Context, req *pb.UserRenewRequest) (*pb.UserResponse, error) {
+	logrus.Debugf("rpc call: user renew cert: %s", req.Username)
 	var ut []*pb.UserResponse_User
 	user, err := ovpm.GetUser(req.Username)
 	if err != nil {
@@ -93,6 +97,7 @@ func (s *UserService) Renew(ctx context.Context, req *pb.UserRenewRequest) (*pb.
 }
 
 func (s *UserService) GenConfig(ctx context.Context, req *pb.UserGenConfigRequest) (*pb.UserGenConfigResponse, error) {
+	logrus.Debugf("rpc call: user genconfig: %s", req.Username)
 	user, err := ovpm.GetUser(req.Username)
 	if err != nil {
 		return nil, err
@@ -108,6 +113,7 @@ func (s *UserService) GenConfig(ctx context.Context, req *pb.UserGenConfigReques
 type VPNService struct{}
 
 func (s *VPNService) Status(ctx context.Context, req *pb.VPNStatusRequest) (*pb.VPNStatusResponse, error) {
+	logrus.Debugf("rpc call: vpn status")
 	server, err := ovpm.GetServerInstance()
 	if err != nil {
 		return nil, err
@@ -128,6 +134,7 @@ func (s *VPNService) Status(ctx context.Context, req *pb.VPNStatusRequest) (*pb.
 }
 
 func (s *VPNService) Init(ctx context.Context, req *pb.VPNInitRequest) (*pb.VPNInitResponse, error) {
+	logrus.Debugf("rpc call: vpn init")
 	if err := ovpm.Init(req.Hostname, req.Port); err != nil {
 		logrus.Errorf("server can not be created: %v", err)
 	}
@@ -135,10 +142,10 @@ func (s *VPNService) Init(ctx context.Context, req *pb.VPNInitRequest) (*pb.VPNI
 }
 
 func (s *VPNService) Apply(ctx context.Context, req *pb.VPNApplyRequest) (*pb.VPNApplyResponse, error) {
+	logrus.Debugf("rpc call: vpn apply")
 	if err := ovpm.Emit(); err != nil {
 		logrus.Errorf("can not apply configuration: %v", err)
 		return nil, err
 	}
-	logrus.Info("changes applied")
 	return &pb.VPNApplyResponse{}, nil
 }

cmd/ovpm/main.go

@@ -32,7 +32,7 @@ func main() {
 		},
 	}
 	app.Before = func(c *cli.Context) error {
-		logrus.SetLevel(logrus.WarnLevel)
+		logrus.SetLevel(logrus.InfoLevel)
 		if c.GlobalBool("verbose") {
 			logrus.SetLevel(logrus.DebugLevel)
 		}
@@ -180,7 +180,7 @@ func main() {
 							os.Exit(1)
 							return err
 						}
-						logrus.Infof("user certs renewed: '%s'", username)
+						logrus.Infof("user cert renewed: '%s'", username)
 						return nil
 					},
 				},
@@ -217,30 +217,15 @@ func main() {
 						pb.NewVPNServiceClient(conn)
 
 						res, err := userSvc.GenConfig(context.Background(), &pb.UserGenConfigRequest{Username: username})
-						emitToFile(output, res.ClientConfig, 0)
-
 						if err != nil {
 							logrus.Errorf("user config can not be exported %s: %v", username, err)
 							return err
 						}
-						fmt.Printf("exported to %s", output)
+						emitToFile(output, res.ClientConfig, 0)
+						logrus.Infof("exported to %s", output)
 						return nil
 					},
 				},
-				// {
-				// 	Name:  "lock",
-				// 	Usage: "Lock VPN user",
-				// 	Action: func(c *cli.Context) error {
-				// 		return nil
-				// 	},
-				// },
-				// {
-				// 	Name:  "unlock",
-				// 	Usage: "Unlock VPN user",
-				// 	Action: func(c *cli.Context) error {
-				// 		return nil
-				// 	},
-				// },
 			},
 		},
 		{
@@ -327,7 +312,7 @@ func main() {
 									os.Exit(1)
 									return err
 								}
-
+								logrus.Info("ovpm server initialized")
 								break
 							} else if stringInSlice(response, nokayResponses) {
 								return fmt.Errorf("user decided to cancel")
@@ -352,7 +337,7 @@ func main() {
 							os.Exit(1)
 							return err
 						}
-						logrus.Info("changes applied")
+						logrus.Info("changes applied; OpenVPN restarted")
 						return nil
 					},
 				},

cmd/ovpm/utils.go

@@ -2,9 +2,10 @@ package main
 
 import (
 	"fmt"
-	"log"
 	"os"
 
+	"github.com/Sirupsen/logrus"
+
 	"google.golang.org/grpc"
 )
 
@@ -29,7 +30,7 @@ func getConn(port string) *grpc.ClientConn {
 
 	conn, err := grpc.Dial(fmt.Sprintf(":%s", port), grpc.WithInsecure())
 	if err != nil {
-		log.Fatalf("fail to dial: %v", err)
+		logrus.Fatalf("fail to dial: %v", err)
 	}
 	return conn
 

supervisor/supervisor.go

@@ -172,8 +172,10 @@ func (p *Process) setState(state State) {
 func (p *Process) transitionTo(state State) {
 	if p.permittable(state) {
 		p.stateChangeCond.L.Lock()
-		logrus.Infof("transition: '%s' -> '%s'", p.state, state)
-		logrus.Debug(p.out.String())
+		logrus.WithField("cmd", p.executable).Debugf("transition: '%s' -> '%s'", p.state, state)
+		if p.out.Len() > 0 {
+			logrus.Debugf("STDOUT(err): %s", p.out.String())
+		}
 		p.setState(state)
 		go p.run(state)()
 		p.stateChangeCond.L.Unlock()
@@ -183,6 +185,7 @@ func (p *Process) transitionTo(state State) {
 	logrus.Errorf("transition to '%s' from '%s' is not permitted!", p.state, state)
 	return
 }
+
 func (p *Process) newCommand() *exec.Cmd {
 	cmd := exec.Command(p.executable)
 	cmd.Stdout = p.out
@@ -207,6 +210,7 @@ func (p *Process) newCommand() *exec.Cmd {
 	cmd.SysProcAttr = &syscall.SysProcAttr{Credential: &syscall.Credential{Uid: uint32(uid), Gid: uint32(gid)}}
 	return cmd
 }
+
 func (p *Process) run(state State) func() {
 	switch state {
 	case STOPPED:
@@ -224,11 +228,11 @@ func (p *Process) run(state State) func() {
 				p.cmd = p.newCommand()
 				p.lock.Unlock()
 
-				logrus.Infof("starting the process")
+				logrus.Debugf("running %s", p.executable)
 				err = p.cmd.Start()
 				if err != nil {
-					logrus.Warnf("process can not be started: %v", err)
-					logrus.Infof("retrying... (%d/%d)", i, p.maxRetry)
+					logrus.Debugf("process can not be started: %v", err)
+					logrus.Debugf("retrying... (%d/%d)", i, p.maxRetry)
 					continue
 				}
 				break
@@ -240,7 +244,7 @@ func (p *Process) run(state State) func() {
 			}
 
 			// Process started successfully.
-			logrus.Info("process is started")
+			logrus.Debugf("process is started %s PID %d", p.executable, p.cmd.Process.Pid)
 
 			// Process Observer
 			go func() {
@@ -253,7 +257,6 @@ func (p *Process) run(state State) func() {
 				p.done <- err
 				close(p.done)
 			}()
-			logrus.Info("observer goroutine launched")
 			p.transitionTo(RUNNING)
 		}
 	case RUNNING:
@@ -287,7 +290,7 @@ func (p *Process) run(state State) func() {
 			for i := uint(1); i <= p.maxRetry; i++ {
 				select {
 				case <-time.After(3 * time.Second):
-					logrus.Infof("retrying... (%d/%d)", i, p.maxRetry)
+					logrus.Debugf("retrying... (%d/%d)", i, p.maxRetry)
 					err := p.cmd.Process.Signal(os.Interrupt)
 					if err != nil {
 						logrus.Errorf("interrupt signal returned error: %v", err)
@@ -297,7 +300,7 @@ func (p *Process) run(state State) func() {
 						gracefullyStopped = true
 						break
 					}
-					logrus.Errorf("process stopped with error: %v", err)
+					logrus.Debugf("process stopped with error: %v", err)
 					break
 
 				}
@@ -312,17 +315,16 @@ func (p *Process) run(state State) func() {
 				}
 				<-p.done
 			}
-			logrus.Info("process stopped")
+			logrus.Debugf("process stopped %s", p.executable)
 			p.transitionTo(STOPPED)
 		}
 	case FAILED:
 		return func() {
-			logrus.Fatal("process operation failed state")
+			logrus.Fatalf("failed to launch process: %s", p.executable)
 		}
 	case EXITED:
 		return func() {
-			logrus.Errorln("process exited unexpectedly")
-			logrus.Printf("out: %s", p.out.String())
+			logrus.Errorf("process exited unexpectedly: %s", p.executable)
 			os.Exit(1)
 		}
 	default: // UNKNOWN

user.go

@@ -127,7 +127,7 @@ func (u *DBUser) Delete() error {
 		SerialNumber: crt.SerialNumber.Text(16),
 	})
 	db.Unscoped().Delete(&u)
-
+	logrus.Infof("user deleted: %s", u.GetUsername())
 	err = Emit()
 	if err != nil {
 		return err
@@ -144,6 +144,7 @@ func (u *DBUser) ResetPassword(password string) error {
 		return fmt.Errorf("user password can not be updated %s: %v", u.Username, err)
 	}
 	db.Save(u)
+	logrus.Infof("user password reset: %s", u.GetUsername())
 	return nil
 }
 
@@ -175,6 +176,7 @@ func (u *DBUser) Sign() error {
 	u.ServerSerialNumber = server.SerialNumber
 
 	db.Save(&u)
+	logrus.Infof("user renewed cert: %s", u.GetUsername())
 	return nil
 }
 

vpn.go

@@ -123,6 +123,7 @@ func Init(hostname string, port string) error {
 			continue
 		}
 	}
+	logrus.Infof("server initialized")
 	return nil
 }
 
@@ -279,10 +280,10 @@ func Emit() error {
 		return fmt.Errorf("can not emit crl: %s", err)
 	}
 
-	logrus.Info("changes are applied to the filesystem")
+	logrus.Info("configurations emitted to the filesystem")
 
 	RestartVPNProc()
-	logrus.Info("OpenVPN process is restarted")
+	logrus.Info("OpenVPN process is restarting")
 
 	return nil
 }
@@ -503,7 +504,7 @@ func checkOpenVPNExecutable() bool {
 		logrus.Error("openvpn is not installed ✘")
 		return false
 	}
-	logrus.Infof("openvpn executable detected: %s  ✔", executable)
+	logrus.Debugf("openvpn executable detected: %s  ✔", executable)
 	return true
 }
 
@@ -511,10 +512,10 @@ func getOpenVPNExecutable() string {
 	cmd := exec.Command("which", "openvpn")
 	output, err := cmd.Output()
 	if err != nil {
-		logrus.Infof("openvpn is not installed: %s  ✘", err)
+		logrus.Errorf("openvpn is not installed: %s  ✘", err)
 		return ""
 	}
-	logrus.Infof("openvpn executable detected: %s  ✔", strings.TrimSpace(string(output[:])))
+	logrus.Debugf("openvpn executable detected: %s  ✔", strings.TrimSpace(string(output[:])))
 	return strings.TrimSpace(string(output[:]))
 }
 
@@ -525,7 +526,7 @@ func checkOpenSSLExecutable() bool {
 		logrus.Errorf("openssl is not installed: %s  ✘", err)
 		return false
 	}
-	logrus.Infof("openssl executable detected: %s  ✔", strings.TrimSpace(string(output[:])))
+	logrus.Debugf("openssl executable detected: %s  ✔", strings.TrimSpace(string(output[:])))
 	return true
 }
 
@@ -536,7 +537,7 @@ func checkIptablesExecutable() bool {
 		logrus.Errorf("iptables is not installed: %s  ✘", err)
 		return false
 	}
-	logrus.Infof("iptables executable detected: %s  ✔", strings.TrimSpace(string(output[:])))
+	logrus.Debugf("iptables executable detected: %s  ✔", strings.TrimSpace(string(output[:])))
 	return true
 }