Add some logging

Author: silvanocerza

flasher/flasher.go

@@ -24,6 +24,7 @@ import (
 	"time"
 
 	"github.com/arduino/go-paths-helper"
+	"github.com/sirupsen/logrus"
 	"go.bug.st/serial"
 )
 
@@ -74,9 +75,10 @@ func openSerial(portAddress string) (serial.Port, error) {
 			// Try another baudrate
 			continue
 		}
+		logrus.Infof("Opened port %s at %s", portAddress, baudRate)
 
 		if err := port.SetReadTimeout(30 * time.Second); err != nil {
-			return nil, fmt.Errorf("Could not set timeout on serial port: %s", err)
+			return nil, fmt.Errorf("could not set timeout on serial port: %s", err)
 		}
 
 		return port, nil

flasher/nina.go

@@ -24,25 +24,31 @@ import (
 	"crypto/md5"
 	"encoding/binary"
 	"fmt"
+	"strconv"
 	"time"
 
 	"github.com/arduino/go-paths-helper"
+	"github.com/sirupsen/logrus"
 	"go.bug.st/serial"
 )
 
 // NewNinaFlasher creates an new instance of NinaFlasher
 func NewNinaFlasher(portAddress string) (*NinaFlasher, error) {
 	port, err := openSerial(portAddress)
 	if err != nil {
+		logrus.Error(err)
 		return nil, err
 	}
 	f := &NinaFlasher{port: port}
 	payloadSize, err := f.getMaximumPayloadSize()
 	if err != nil {
+		logrus.Error(err)
 		return nil, err
 	}
 	if payloadSize < 1024 {
-		return nil, fmt.Errorf("programmer reports %d as maximum payload size (1024 is needed)", payloadSize)
+		err = fmt.Errorf("programmer reports %d as maximum payload size (1024 is needed)", payloadSize)
+		logrus.Error(err)
+		return nil, err
 	}
 	f.payloadSize = int(payloadSize)
 	return f, nil
@@ -55,17 +61,21 @@ type NinaFlasher struct {
 
 // FlashFirmware in board connected to port using data from firmwareFile
 func (f *NinaFlasher) FlashFirmware(firmwareFile *paths.Path) error {
+	logrus.Infof("Flashing firmware %s", firmwareFile)
 	if err := f.hello(); err != nil {
+		logrus.Error(err)
 		return err
 	}
 
 	data, err := firmwareFile.ReadFile()
 	if err != nil {
+		logrus.Error(err)
 		return err
 	}
 
 	firmwareOffset := 0x0000
 	if err := f.flashChunk(firmwareOffset, data); err != nil {
+		logrus.Error(err)
 		return err
 	}
 
@@ -79,7 +89,9 @@ func (f *NinaFlasher) FlashCertificates(certificatePaths *paths.PathList) error
 
 // Close the port used by this flasher
 func (f *NinaFlasher) Close() error {
-	return f.port.Close()
+	err := f.port.Close()
+	logrus.Error(err)
+	return err
 }
 
 // Ping the programmer to see if it is alive.
@@ -93,6 +105,7 @@ func (f *NinaFlasher) hello() error {
 		Payload: nil,
 	})
 	if err != nil {
+		logrus.Error(err)
 		return err
 	}
 
@@ -103,6 +116,7 @@ func (f *NinaFlasher) hello() error {
 	res := make([]byte, 65535)
 	n, err := f.port.Read(res)
 	if err != nil {
+		logrus.Error(err)
 		return err
 	}
 	// flush eventual leftover from the rx buffer
@@ -111,11 +125,15 @@ func (f *NinaFlasher) hello() error {
 	}
 
 	if res[0] != 'v' {
-		return FlasherError{err: "Programmer is not responding"}
+		err = FlasherError{err: "Programmer is not responding"}
+		logrus.Error(err)
+		return err
 	}
 	if string(res) != "v10000" {
 		// TODO: Do we really need this check? What is it trying to verify?
-		return FlasherError{err: fmt.Sprintf("Programmer version mismatch, v10000 needed: %s", res)}
+		err = FlasherError{err: fmt.Sprintf("Programmer version mismatch, v10000 needed: %s", res)}
+		logrus.Error(err)
+		return err
 	}
 	return nil
 }
@@ -126,17 +144,19 @@ func (f *NinaFlasher) flashChunk(offset int, buffer []byte) error {
 	bufferLength := len(buffer)
 
 	if err := f.erase(uint32(offset), uint32(bufferLength)); err != nil {
+		logrus.Error(err)
 		return err
 	}
 
 	for i := 0; i < bufferLength; i += chunkSize {
-		// fmt.Printf("\rFlashing: " + strconv.Itoa((i*100)/bufferLength) + "%%")
+		logrus.Debugf("Flashing chunk: %s%%", strconv.Itoa((i*100)/bufferLength))
 		start := i
 		end := i + chunkSize
 		if end > bufferLength {
 			end = bufferLength
 		}
 		if err := f.write(uint32(offset+i), buffer[start:end]); err != nil {
+			logrus.Error(err)
 			return err
 		}
 	}
@@ -154,12 +174,14 @@ func (f *NinaFlasher) getMaximumPayloadSize() (uint16, error) {
 		Payload: nil,
 	})
 	if err != nil {
+		logrus.Error(err)
 		return 0, err
 	}
 
 	// Receive response
 	res := make([]byte, 2)
 	if err := f.serialFillBuffer(res); err != nil {
+		logrus.Error(err)
 		return 0, err
 	}
 	return (uint16(res[0]) << 8) + uint16(res[1]), nil
@@ -171,10 +193,13 @@ func (f *NinaFlasher) serialFillBuffer(buffer []byte) error {
 	for read < len(buffer) {
 		n, err := f.port.Read(buffer[read:])
 		if err != nil {
+			logrus.Error(err)
 			return err
 		}
 		if n == 0 {
-			return FlasherError{err: "Serial port closed unexpectedly"}
+			err = FlasherError{err: "Serial port closed unexpectedly"}
+			logrus.Error(err)
+			return err
 		}
 		read += n
 	}
@@ -183,14 +208,18 @@ func (f *NinaFlasher) serialFillBuffer(buffer []byte) error {
 
 // sendCommand sends the data over serial port to connected board
 func (f *NinaFlasher) sendCommand(data CommandData) error {
+	logrus.Debugf("sending command data %s", data)
 	buff := new(bytes.Buffer)
 	if err := binary.Write(buff, binary.BigEndian, data.Command); err != nil {
+		logrus.Error(err)
 		return err
 	}
 	if err := binary.Write(buff, binary.BigEndian, data.Address); err != nil {
+		logrus.Error(err)
 		return err
 	}
 	if err := binary.Write(buff, binary.BigEndian, data.Value); err != nil {
+		logrus.Error(err)
 		return err
 	}
 	var length uint16
@@ -200,6 +229,7 @@ func (f *NinaFlasher) sendCommand(data CommandData) error {
 		length = uint16(len(data.Payload))
 	}
 	if err := binary.Write(buff, binary.BigEndian, length); err != nil {
+		logrus.Error(err)
 		return err
 	}
 	if data.Payload != nil {
@@ -209,11 +239,13 @@ func (f *NinaFlasher) sendCommand(data CommandData) error {
 	for {
 		sent, err := f.port.Write(bufferData)
 		if err != nil {
+			logrus.Error(err)
 			return err
 		}
 		if sent == len(bufferData) {
 			break
 		}
+		logrus.Debugf("Sent %d bytes out of %d", sent, len(bufferData))
 		bufferData = bufferData[sent:]
 	}
 	return nil
@@ -229,20 +261,25 @@ func (f *NinaFlasher) read(address uint32, length uint32) ([]byte, error) {
 		Payload: nil,
 	})
 	if err != nil {
+		logrus.Error(err)
 		return nil, err
 	}
 
 	// Receive response
 	result := make([]byte, length)
 	if err := f.serialFillBuffer(result); err != nil {
+		logrus.Error(err)
 		return nil, err
 	}
 	ack := make([]byte, 2)
 	if err := f.serialFillBuffer(ack); err != nil {
+		logrus.Error(err)
 		return nil, err
 	}
 	if string(ack) != "OK" {
-		return nil, FlasherError{err: fmt.Sprintf("Missing ack on read: %s, result: %s", ack, result)}
+		err = FlasherError{err: fmt.Sprintf("Missing ack on read: %s, result: %s", ack, result)}
+		logrus.Error(err)
+		return nil, err
 	}
 	return result, nil
 }
@@ -257,16 +294,20 @@ func (f *NinaFlasher) write(address uint32, buffer []byte) error {
 		Payload: buffer,
 	})
 	if err != nil {
+		logrus.Error(err)
 		return err
 	}
 
 	// wait acknowledge
 	ack := make([]byte, 2)
 	if err := f.serialFillBuffer(ack); err != nil {
+		logrus.Error(err)
 		return err
 	}
 	if string(ack) != "OK" {
-		return FlasherError{err: fmt.Sprintf("Missing ack on write: %s", ack)}
+		err = FlasherError{err: fmt.Sprintf("Missing ack on write: %s", ack)}
+		logrus.Error(err)
+		return err
 	}
 	return nil
 }
@@ -281,16 +322,20 @@ func (f *NinaFlasher) erase(address uint32, length uint32) error {
 		Payload: nil,
 	})
 	if err != nil {
+		logrus.Error(err)
 		return err
 	}
 
 	// wait acknowledge
 	ack := make([]byte, 2)
 	if err := f.serialFillBuffer(ack); err != nil {
+		logrus.Error(err)
 		return err
 	}
 	if string(ack) != "OK" {
-		return FlasherError{err: fmt.Sprintf("Missing ack on erase: %s", ack)}
+		err = FlasherError{err: fmt.Sprintf("Missing ack on erase: %s", ack)}
+		logrus.Error(err)
+		return err
 	}
 	return nil
 }
@@ -307,33 +352,39 @@ func (f *NinaFlasher) md5sum(data []byte) error {
 		Payload: nil,
 	})
 	if err != nil {
+		logrus.Error(err)
 		return err
 	}
 
 	// Wait acknowledge
 	ack := make([]byte, 2)
 	if err := f.serialFillBuffer(ack); err != nil {
+		logrus.Error(err)
 		return err
 	}
 	if string(ack) != "OK" {
-		return FlasherError{err: fmt.Sprintf("Missing ack on md5sum: %s", ack)}
+		err := FlasherError{err: fmt.Sprintf("Missing ack on md5sum: %s", ack)}
+		logrus.Error(err)
+		return err
 	}
 
 	// Wait md5
-	md5sum := make([]byte, 16)
-	if err := f.serialFillBuffer(md5sum); err != nil {
+	md5sumfromdevice := make([]byte, 16)
+	if err := f.serialFillBuffer(md5sumfromdevice); err != nil {
 		return err
 	}
 
-	md5sumfromdevice := hasher.Sum(nil)
+	md5sum := hasher.Sum(nil)
+	logrus.Debugf("md5 read from device %s", md5sumfromdevice)
+	logrus.Debugf("md5 of data %s", md5sum)
 
 	for i := 0; i < 16; i++ {
-		if md5sumfromdevice[i] != md5sum[i] {
-			return &FlasherError{err: "MD5sum failed"}
+		if md5sum[i] != md5sumfromdevice[i] {
+			err := FlasherError{err: "MD5sum failed"}
+			logrus.Error(err)
+			return err
 		}
 	}
 
-	// log.Println("Integrity ok")
-
 	return nil
 }