Commit 580f41ae authored by Anders Jensen Løvig's avatar Anders Jensen Løvig
Browse files

Log overhaul

parent a8ceffa8
......@@ -47,7 +47,7 @@ func init() {
// Init configuration
server.Config, err = network.LoadConfig()
if err != nil {
log.Fatal("ERROR: " + err.Error())
log.Fatal("fatal:", err)
}
portStr := fmt.Sprintf(":%d", opts.Port)
......@@ -60,7 +60,7 @@ func init() {
}
}
if serialNumber == nil {
log.Fatal("Server is not on server list")
log.Fatal("fatal: server is not on server list")
}
server.Config.CertPath = fmt.Sprintf("config/cert/server/s%d.crt", serialNumber)
......@@ -90,7 +90,7 @@ var clientHandlers = map[string]network.MessageHandler{
var ballot election.Ballot
err := data.Unmarshal(&ballot)
if err != nil {
log.Println("ERROR: " + err.Error())
log.Println("Main: error:", err)
} else {
go server.Election.HandleBallot(conn.SerialNumber(), &ballot)
}
......@@ -106,7 +106,7 @@ var serverHandlers = map[string]network.MessageHandler{
var tally election.Tally
err := data.Unmarshal(&tally)
if err != nil {
log.Println("ERROR: " + err.Error())
log.Println("Main: error:", err)
} else {
go server.Election.HandleTally("", &tally)
}
......@@ -123,14 +123,12 @@ func main() {
}
})
if err != nil {
log.Println("ERROR: " + err.Error())
log.Fatal("Failed to start server")
log.Fatal("Main: fatal:", err)
}
log.Println("==================== Collecting ====================")
err = server.Election.Start()
if err != nil {
log.Println("ERROR: " + err.Error())
log.Fatal("Failed to start election")
log.Fatal("Main: fatal:", err)
}
time.Sleep(1 * time.Second) // Grace period
......@@ -142,8 +140,6 @@ func main() {
}
func closeCallback(reason election.Reason) {
log.Println("DEBUG: Close callback")
connections := 0
msgClosed := network.NewMessage(election.MsgClosing, nil)
......@@ -152,27 +148,26 @@ func closeCallback(reason election.Reason) {
if address != server.Address {
conn, err := server.Server.Connect(address, serverHandlers)
if err != nil {
log.Println("Failed to connect to", address, err.Error())
log.Println("Main: error:", err)
continue
}
connections++
err = conn.WriteMessage(msgClosed)
if err != nil {
log.Println("ERROR: ", err.Error())
log.Println("Main: error:", err)
}
}
}
if connections == 0 {
log.Fatal("Failed to connect to other servers")
log.Fatal("Main: fatal: could not connect to servers")
}
server.Done <- true
}
func tallyCallback(tally *election.Tally) {
log.Println("DEBUG: Tally callback")
log.Println("===================== Tallying =====================")
server.Election.HandleTally("", tally)
......@@ -184,15 +179,13 @@ func tallyCallback(tally *election.Tally) {
}
func resultCallback(result *election.Result) {
log.Println("DEBUG: Result callback")
log.Println("====================== Result ======================")
if result == nil {
log.Printf("No votes received")
log.Printf("Main: no votes received")
} else {
percentage := (float64(result.Tally) / float64(result.Votes)) * 100
log.Printf("Final result: %d of %d (%.2f%%) voted 1\n", result.Tally, result.Votes, percentage)
log.Printf("Main: final result: %d of %d (%.2f%%) voted 1\n", result.Tally, result.Votes, percentage)
}
server.Done <- true
......
......@@ -43,7 +43,7 @@ func init() {
// Load config
config, err := network.LoadConfig()
if err != nil {
log.Fatal("ERROR: " + err.Error())
log.Fatal("fatal: " + err.Error())
}
config.CertPath = opts.Cert
config.KeyPath = opts.Key
......@@ -61,13 +61,13 @@ func main() {
vote := inputVote()
if vote != 0 && vote != 1 {
fmt.Println("Vote must be 0 or 1")
fmt.Println("error: vote must be 0 or 1")
os.Exit(0)
}
config, err := network.LoadConfig()
if err != nil {
log.Fatal("ERROR: " + err.Error())
log.Fatal("fatal: " + err.Error())
}
voter.Config = config
......@@ -85,19 +85,18 @@ func main() {
timeout := network.TimeoutAfter(10 * time.Second)
select {
case <-voter.Done:
log.Println("All servers acknowledged")
log.Println("Main: all servers acknowledged")
case <-timeout:
for address, status := range voter.Acks {
if !status {
log.Println("Did not receive acknowledgment from ", address)
log.Println("Main: no acknowledgment from ", address)
}
}
}
err = voter.Client.Close()
if err != nil {
log.Println("ERROR: " + err.Error())
log.Println("Failed to close client")
log.Println("Main: error: ", err.Error())
}
time.Sleep(1 * time.Second) // Grace period
......@@ -112,12 +111,12 @@ func inputVote() int64 {
reader := bufio.NewReader(os.Stdin)
text, err := reader.ReadString('\n')
if err != nil {
log.Fatal("Failed to read input")
log.Fatal("fatal: could not read input")
}
vote, err := strconv.Atoi(text[0 : len(text)-1])
if err != nil {
fmt.Println("Vote must be an integer")
fmt.Println("error: vote must be an integer")
os.Exit(0)
}
......@@ -149,7 +148,7 @@ func sendBallots(ballots map[election.UniqueID]*election.Ballot) {
},
})
if err != nil {
log.Println("ERROR: " + err.Error())
log.Println("Main: error:", err)
continue
}
ballot := ballots[conn.SerialNumber()]
......@@ -157,7 +156,7 @@ func sendBallots(ballots map[election.UniqueID]*election.Ballot) {
err = conn.WriteMessage(message)
if err != nil {
log.Println("ERROR: " + err.Error())
log.Println("Main: error:", err)
continue
}
voter.Acks[address] = false
......@@ -166,7 +165,6 @@ func sendBallots(ballots map[election.UniqueID]*election.Ballot) {
}
if connectionCount == 0 {
log.Println("FATAL: Could not connect to servers")
os.Exit(1)
log.Fatal("fatal: could not connect to servers")
}
}
......@@ -88,7 +88,7 @@ func (box *BallotBox) Put(ballot *Ballot) error {
defer box.Unlock()
if _, ok := box.ballots[ballot.ID]; ok {
return fmt.Errorf("Already have a ballot with id %s", ballot.ID)
return fmt.Errorf("already have a ballot with id %s", ballot.ID)
}
box.ballots[ballot.ID] = ballot
......@@ -115,10 +115,10 @@ func (box *BallotBox) Tally() *Tally {
valids++
}
} else {
log.Printf("Ballot box (%d) contains share with x=%d\n", box.X, ballot.Share.X)
log.Printf("Election: already contains ballot with x=%d\n", ballot.Share.X)
}
}
log.Printf("processed %d ballots, %d/%d valid", valids, valids, size)
log.Printf("Election: processed %d ballots with %d/%d valid", valids, valids, size)
params := pedersen.NewParams(box.params)
......
......@@ -3,7 +3,7 @@ package election
import (
"bsc-shamir/crypto/common"
"fmt"
"errors"
"log"
"math/big"
"sync"
......@@ -159,7 +159,7 @@ func (election *Election) Start() error {
defer election.Unlock()
if !election.Deadline.After(time.Now()) {
return fmt.Errorf("deadline is in the past")
return errors.New("deadline is in the past")
}
election.Status.Phase = PhaseCollecting
......@@ -176,8 +176,7 @@ func (election *Election) Start() error {
}
}(election)
log.Println("Election started")
log.Printf("Election parameters:\n Voters: %d\n Servers: %d\n Required: %d\n Deadline %s\n",
log.Printf("Election: started with parameters:\n Voters: %d\n Servers: %d\n Required: %d\n Deadline %s\n",
election.Participants.Voters, election.Participants.Servers, election.Participants.RequiredServers,
election.Deadline)
......@@ -196,8 +195,8 @@ func (election *Election) nextPhase(reason Reason) {
if len(election.Status.ClosedServers) < election.Participants.RequiredServers {
// Not enough servers to tally.
election.Status.Phase = PhaseClosed
n := len(election.Status.ClosedServers) - election.Participants.RequiredServers
log.Printf("Need an additional %d servers to tally election\n", n)
n := election.Participants.RequiredServers - len(election.Status.ClosedServers)
log.Printf("Election: waiting for %d more servers to close\n", n)
break
}
// Else enough servers to start tallying
......@@ -225,12 +224,12 @@ func (election *Election) HandleBallot(voterID UniqueID, ballot *Ballot) {
if election.Status.Phase == PhaseCollecting {
if _, ok := election.Status.Turnout[voterID]; ok {
log.Printf("ERROR: Voter %s tried to vote agian\n", voterID)
log.Printf("Election: error: voter %s tried to vote again\n", voterID)
return
}
err := election.ballotBox.Put(ballot)
if err != nil {
log.Print("ERROR: ballot box put:", err.Error())
log.Println("Election: error:", err)
return
}
election.Status.Turnout[voterID] = true
......@@ -239,7 +238,7 @@ func (election *Election) HandleBallot(voterID UniqueID, ballot *Ballot) {
election.nextPhase(ReasonVotes)
}
} else {
log.Printf("Recevied ballot '%s' while election is not collecting ballots\n", ballot.ID)
log.Printf("Election: error: recevied ballot %s outside of collecting phase\n", ballot.ID)
}
}
......@@ -248,12 +247,12 @@ func (election *Election) HandleClosing(id UniqueID) {
election.Lock()
defer election.Unlock()
if election.Status.Phase == PhaseNotStarted {
log.Printf("ERROR: Server %s closed before election started\n", id)
log.Printf("Election: error: server %s closed before election started\n", id)
return
}
if _, ok := election.Status.ClosedServers[id]; ok {
log.Printf("ERROR: Server %s already closed\n", id)
log.Printf("Election: error: server %s already closed\n", id)
return
}
election.Status.ClosedServers[id] = true
......@@ -270,22 +269,22 @@ func (election *Election) HandleTally(serverID UniqueID, tally *Tally) {
election.Lock()
defer election.Unlock()
if election.Status.Phase == PhaseNotStarted {
log.Printf("ERROR: Server %s tallied before election started\n", serverID)
log.Printf("Election: error: server %s tallied before election started\n", serverID)
return
}
if _, ok := election.Status.ClosedServers[serverID]; !ok {
log.Printf("ERROR: Received tally from server %s, who have not closed\n", serverID)
log.Printf("Election: error: received tally from server %s, who have not closed\n", serverID)
return
}
if _, ok := election.Status.TalliedServers[serverID]; ok {
log.Printf("ERROR: Server %s have already sent a tally\n", serverID)
log.Printf("Election: error: server %s have already sent a tally\n", serverID)
return
}
err := election.tallyBox.Put(tally)
if err != nil {
log.Println("ERROR: " + err.Error())
log.Println("Election: error:", err)
return
}
election.Status.TalliedServers[serverID] = true
......
......@@ -53,10 +53,10 @@ func (box *TallyBox) Put(tally *Tally) error {
defer box.Unlock()
if _, ok := box.tallies[tally.ID]; ok {
return fmt.Errorf("Already have a tally with id %s", tally.ID)
return fmt.Errorf("already have a tally with id %s", tally.ID)
}
if !tally.Verify(box.params) {
return fmt.Errorf("Could not verify tally %s", tally.ID)
return fmt.Errorf("could not verify tally %s", tally.ID)
}
box.tallies[tally.ID] = tally
......
......@@ -4,6 +4,7 @@ import (
"bsc-shamir/election"
"crypto/tls"
"crypto/x509"
"errors"
"fmt"
"log"
"net"
......@@ -40,6 +41,7 @@ type Client struct {
func NewClient(config *Config) *Client {
tlsConfig := createClientConfig(config.RootPath, config.CertPath, config.KeyPath)
logName = "Client"
return &Client{
connections: make(map[net.Conn]bool),
mutex: sync.Mutex{},
......@@ -68,7 +70,7 @@ func (client *Client) Connect(address string, handlers map[string]MessageHandler
return nil, err
}
log.Println("Connected to " + address)
log.Printf("%s: connected: %s\n", logName, tlsConn.RemoteAddr())
serialNumber, err := client.checkConnection(address, tlsConn)
if err != nil {
tlsConn.Close()
......@@ -88,11 +90,11 @@ func (client *Client) Connect(address string, handlers map[string]MessageHandler
func (client *Client) checkConnection(address string, conn *tls.Conn) (election.UniqueID, error) {
verifiedChains := conn.ConnectionState().VerifiedChains
if len(verifiedChains) != 1 {
return "", fmt.Errorf("%s presents multiple certificate chains", conn.RemoteAddr().String())
return "", errors.New("multiple verified chains")
}
cert := verifiedChains[0][0]
if len(cert.ExtKeyUsage) == 0 {
return "", fmt.Errorf("Verified chain does not have extended key usages")
return "", errors.New("no extended key usages")
}
_, err := cert.Verify(client.verifyOptions)
if err != nil {
......@@ -100,7 +102,7 @@ func (client *Client) checkConnection(address string, conn *tls.Conn) (election.
}
if sn := client.config.Servers[address]; sn.Cmp(cert.SerialNumber) != 0 {
return "", fmt.Errorf("Server %s presented valid certificate with unexpected serial number %s. ", conn.RemoteAddr().String(), cert.SerialNumber)
return "", fmt.Errorf("unexpected serial number %s", cert.SerialNumber)
}
return election.UniqueID(cert.SerialNumber.String()), nil
......
......@@ -36,13 +36,13 @@ type Config struct {
func LoadConfig() (*Config, error) {
data, err := ioutil.ReadFile(configPath)
if err != nil {
return nil, fmt.Errorf("Failed to read config: %s", err.Error())
return nil, fmt.Errorf("could not read config: %s", err)
}
var config Config
err = json.Unmarshal(data, &config)
if err != nil {
return nil, fmt.Errorf("Failed to parse config: %s", err.Error())
return nil, fmt.Errorf("could not parse config: %s", err)
}
return &config, nil
......@@ -79,7 +79,7 @@ func (c *Config) Save() {
func createRootPool(rootPath string) *x509.CertPool {
roots := x509.NewCertPool()
if !roots.AppendCertsFromPEM(loadPEM(rootPath)) {
log.Fatal("FATAL: Could not parse root certificate")
log.Fatal("fatal: could not parse root certificate")
}
return roots
......@@ -88,7 +88,7 @@ func createRootPool(rootPath string) *x509.CertPool {
func loadPEM(path string) []byte {
pem, err := ioutil.ReadFile(path)
if err != nil {
log.Fatal("FATAL: " + err.Error())
log.Fatal("fatal:", err)
}
return pem
}
......@@ -96,7 +96,7 @@ func loadPEM(path string) []byte {
func loadKeyPair(certPath, keyPath string) tls.Certificate {
crt, err := tls.LoadX509KeyPair(certPath, keyPath)
if err != nil {
log.Fatal("Failed to load server certificate and key: " + err.Error())
log.Fatal("fatal: Failed to load server certificate and key:", err)
}
return crt
}
......
......@@ -98,16 +98,13 @@ func (c *Conn) WriteMessage(message *Message) error {
c.writeMutex.Lock()
defer c.writeMutex.Unlock()
log.Printf("Sending message '%s' to %s\n", message.Command, c.RemoteAddr().String())
log.Printf("%s: sending message '%s' to %s\n", logName, message.Command, c.RemoteAddr().String())
data, err := marshal(message)
if err != nil {
return err
}
data := marshal(message)
// Send data size first then data
binary.BigEndian.PutUint32(c.writeBuffer, uint32(len(data)))
_, err = c.Write(c.writeBuffer)
_, err := c.Write(c.writeBuffer)
if err != nil {
return err
}
......
......@@ -33,13 +33,9 @@ type Message struct {
// NewMessage returns a message with given command and data v
func NewMessage(command string, v interface{}) *Message {
data, err := marshal(v)
if err != nil {
log.Fatal("Failed to marshal: " + err.Error())
}
return &Message{
Command: command,
Data: data,
Data: marshal(v),
}
}
......@@ -65,17 +61,13 @@ func readMessage(reader *bufio.Reader) (*Message, error) {
}
func writeMessage(conn net.Conn, message *Message) error {
log.Printf("Sending message '%s' to %s", message.Command, conn.RemoteAddr().String())
data, err := marshal(message)
if err != nil {
return err
}
log.Printf("%s: sending '%s' to %s", logName, message.Command, conn.RemoteAddr())
data := marshal(message)
sizeBuffer := make([]byte, 4)
binary.BigEndian.PutUint32(sizeBuffer, uint32(len(data)))
_, err = conn.Write(sizeBuffer)
_, err := conn.Write(sizeBuffer)
if err != nil {
return err
}
......@@ -88,9 +80,12 @@ func writeMessage(conn net.Conn, message *Message) error {
return nil
}
// To avoid code duplication. Easier to change marshalling
func marshal(v interface{}) ([]byte, error) {
return json.Marshal(v)
func marshal(v interface{}) []byte {
data, err := json.Marshal(v)
if err != nil {
panic(err)
}
return data
}
func unmarshal(data []byte, v interface{}) error {
......@@ -109,37 +104,35 @@ func messageLoop(conn *Conn) {
// First wait for a message and check the returned error.
message, err := readMessage(reader)
if err == io.EOF {
log.Println("Connection closed from " + conn.RemoteAddr().String())
log.Printf("%s: connection closed: %s\n", logName, conn.RemoteAddr())
break
} else if err != nil {
if !conn.closing {
log.Println("ERROR:" + err.Error())
log.Printf("%s: error: %s\n", logName, err)
}
log.Println("Closing connection to " + conn.RemoteAddr().String())
log.Printf("%s: closing connection: %s\n", logName, conn.RemoteAddr())
break
}
// If no error, we let the appropiate message handler do the work
if handler, ok := conn.messageHandlers[message.Command]; ok {
// Spawn go-routine so the message loop can listen for the next message
log.Printf("Received message '%s' from %s\n",
message.Command, conn.RemoteAddr().String())
log.Printf("%s: received message '%s' from %s\n", logName, message.Command, conn.RemoteAddr())
go func(handler MessageHandler) {
response := handler(conn, message.Data)
if response != nil {
mutex.Lock()
err := writeMessage(conn, response)
if err != nil {
log.Println("ERROR: " + err.Error())
log.Printf("%s: error: %s\n", logName, err)
}
mutex.Unlock()
}
}(handler)
} else {
// Zero tolerance for faulty servers. Just close the connection.
log.Printf("ERROR: Unknown message '%s' recevied from %s\n",
message.Command, conn.RemoteAddr().String())
log.Println("Closing connection to " + conn.RemoteAddr().String())
log.Printf("%s: error: %s sent unknown message: %s\n", logName, conn.RemoteAddr(), message.Command)
log.Printf("%s: closing connection: %s\n", logName, conn.RemoteAddr())
break
}
}
......
......@@ -4,6 +4,7 @@ import (
"bsc-shamir/election"
"crypto/tls"
"crypto/x509"
"errors"
"fmt"
"log"
"net"
......@@ -39,6 +40,7 @@ type Server struct {
// NewServer returns a new server using the provided message handlers
func NewServer(config *Config) *Server {
tlsConfig := createServerConfig(config.RootPath, config.CertPath, config.KeyPath)
logName = "Server"
return &Server{
Client: Client{
connections: make(map[net.Conn]bool),
......@@ -88,7 +90,7 @@ func (server *Server) Start(port int, acceptCallback func(ConnType) map[string]M
if err != nil {
return err
}
log.Println("Listening on address: " + addr + ":" + portStr)
log.Printf("%s: listening on address: %s\n", logName, addr+":"+portStr)
go server.listen(listener, acceptCallback)
return nil
......@@ -129,7 +131,7 @@ func (server *Server) listen(listener net.Listener, acceptCallback func(ConnType
conn, err := listener.Accept()
if err != nil {
if !server.closing {
log.Println("ERROR: " + err.Error())
log.Printf("%s: error: %s\n", logName, err)
}
break
}
......@@ -137,22 +139,22 @@ func (server *Server) listen(listener net.Listener, acceptCallback func(ConnType
tlsConn := conn.(*tls.Conn)
// Perform TLS handshake to get client certificates
if err := tlsConn.Handshake(); err != nil {
fmt.Println("ERROR: Failed to handshake:", err)
log.Printf("%s: error: %s\n", logName, err)
return
}
t, sn, err := server.checkConnection(tlsConn)
if err != nil {
conn.Close()
log.Println("ERROR: " + err.Error())
log.Printf("Closing connection from %s\n", conn.RemoteAddr().String())
log.Printf("%s: error: %s\n", logName, err)
log.Printf("%s: closing connection: %s\n", logName, conn.RemoteAddr())
continue
}
if t == ConnTypeClient {
log.Println("Accepted client connection from ", conn.RemoteAddr().String())
log.Printf("%s: accepted client connection: %s\n", logName, conn.RemoteAddr())
} else {
log.Println("Accepted server connection from ", conn.RemoteAddr().String())
log.Printf("%s: accepted server connection: %s\n", logName, conn.RemoteAddr())
}
go server.handleConnection(newConn(t, tlsConn, sn, acceptCallback(t)))
......@@ -164,14 +166,14 @@ func (server *Server) listen(listener net.Listener, acceptCallback func(ConnType
func (server *Server) checkConnection(conn *tls.Conn) (ConnType, election.UniqueID, error) {
verifiedChains := conn.ConnectionState().VerifiedChains
if len(verifiedChains) == 0 {
return 0, "", fmt.Errorf("%s have no verified certificate chains", conn.RemoteAddr().String())
return 0, "", errors.New("no verified chains")
}
if len(verifiedChains) != 1 {
return 0, "", fmt.Errorf("%s presents multiple certificate chains", conn.RemoteAddr().String())