Fix error handling and improve logs for record, activate commands (#35)

* fix error handling

* fix error messages, move logrus to json

Author: danielpaulus

main.go

@@ -14,15 +14,15 @@ import (
 	log "github.com/sirupsen/logrus"
 )
 
-const version = "v0.1-alpha"
+const version = "v0.2-beta"
 
 func main() {
 	usage := fmt.Sprintf(`Q.uickTime V.ideo H.ack (qvh) %s
 
 Usage:
   qvh devices [-v]
   qvh activate [--udid=<udid>] [-v]
-  qvh record <h264file> <wavfile> [-v]
+  qvh record <h264file> <wavfile> [-v] [--udid=<udid>]
   qvh gstreamer [-v]
   qvh --version | version
 
@@ -42,6 +42,7 @@ The commands work as following:
 	gstreamer   qvh will open a new window and push AV data to gstreamer.
   `, version)
 	arguments, _ := docopt.ParseDoc(usage)
+	log.SetFormatter(&log.JSONFormatter{})
 
 	verboseLoggingEnabled, _ := arguments.Bool("-v")
 	if verboseLoggingEnabled {
@@ -103,18 +104,6 @@ func startGStreamer(udid string) {
 	startWithConsumer(gStreamer, udid)
 }
 
-func waitForSigInt(stopSignalChannel chan interface{}) {
-	c := make(chan os.Signal, 1)
-	signal.Notify(c, os.Interrupt)
-	go func() {
-		for sig := range c {
-			log.Debugf("Signal received: %s", sig)
-			var stopSignal interface{}
-			stopSignalChannel <- stopSignal
-		}
-	}()
-}
-
 // Just dump a list of what was discovered to the console
 func devices() {
 	deviceList, err := screencapture.FindIosDevices()
@@ -134,11 +123,16 @@ func devices() {
 // This command is for testing if we can enable the hidden Quicktime device config
 func activate(udid string) {
 	device, err := screencapture.FindIosDevice(udid)
+	if err != nil {
+		printErrJSON(err, "no device found to activate")
+		return
+	}
 
 	log.Debugf("Enabling device: %v", device)
 	device, err = screencapture.EnableQTConfig(device)
 	if err != nil {
-		log.Fatal("Error enabling QT config", err)
+		printErrJSON(err, "Error enabling QT config")
+		return
 	}
 
 	printJSON(map[string]interface{}{
@@ -185,27 +179,45 @@ func record(h264FilePath string, wavFilePath string, udid string) {
 }
 
 func startWithConsumer(consumer screencapture.CmSampleBufConsumer, udid string) {
-	activate(udid)
-
-	deviceList, err := screencapture.FindIosDevices()
-
+	device, err := screencapture.FindIosDevice(udid)
 	if err != nil {
-		log.Fatal("Error finding iOS Devices", err)
+		printErrJSON(err, "no device found to activate")
+		return
 	}
 
-	dev := deviceList[0]
+	device, err = screencapture.EnableQTConfig(device)
+	if err != nil {
+		printErrJSON(err, "Error enabling QT config")
+		return
+	}
 
 	adapter := screencapture.UsbAdapter{}
 	stopSignal := make(chan interface{})
 	waitForSigInt(stopSignal)
 	mp := screencapture.NewMessageProcessor(&adapter, stopSignal, consumer)
 
-	adapter.StartReading(dev, &mp, stopSignal)
+	err = adapter.StartReading(device, &mp, stopSignal)
+	if err != nil {
+		printErrJSON(err, "failed connecting to usb")
+	}
+}
+
+func waitForSigInt(stopSignalChannel chan interface{}) {
+	c := make(chan os.Signal, 1)
+	signal.Notify(c, os.Interrupt)
+	go func() {
+		for sig := range c {
+			log.Debugf("Signal received: %s", sig)
+			var stopSignal interface{}
+			stopSignalChannel <- stopSignal
+		}
+	}()
 }
+
 func printErrJSON(err error, msg string) {
 	printJSON(map[string]interface{}{
-		"originalError": err.Error(),
-		"message":       msg,
+		"original_error": err.Error(),
+		"error_message":  msg,
 	})
 }
 func printJSON(output map[string]interface{}) {

screencapture/activator.go

@@ -24,10 +24,7 @@ func EnableQTConfig(device IosDevice) (IosDevice, error) {
 		return device, nil
 	}
 
-	err = sendQTConfigControlRequest(usbDevice)
-	if err != nil {
-		return IosDevice{}, err
-	}
+	sendQTConfigControlRequest(usbDevice)
 
 	var i int
 	for {
@@ -56,25 +53,22 @@ func EnableQTConfig(device IosDevice) (IosDevice, error) {
 	return device, err
 }
 
-func sendQTConfigControlRequest(device *gousb.Device) error {
+func sendQTConfigControlRequest(device *gousb.Device) {
 	response := make([]byte, 0)
 	val, err := device.Control(0x40, 0x52, 0x00, 0x02, response)
-
 	if err != nil {
-		log.Warn("Failed sending control transfer for enabling hidden QT config. Seems like this happens sometimes but it still works usually.", err)
+		log.Warnf("Failed sending control transfer for enabling hidden QT config. Seems like this happens sometimes but it still works usually: %s", err)
 	}
 	log.Debugf("Enabling QT config RC:%d", val)
-	return nil
 }
 
-func sendQTDisableConfigControlRequest(device *gousb.Device) error {
+func sendQTDisableConfigControlRequest(device *gousb.Device) {
 	response := make([]byte, 0)
 	val, err := device.Control(0x40, 0x52, 0x00, 0x00, response)
 
 	if err != nil {
-		log.Fatal("Failed sending control transfer for disabling hidden QT config", err)
-		return err
+		log.Warnf("Failed sending control transfer for disabling hidden QT config:%s", err)
+
 	}
 	log.Debugf("Disabled QT config RC:%d", val)
-	return nil
 }

screencapture/discovery.go

@@ -68,7 +68,7 @@ func FindIosDevice(udid string) (IosDevice, error) {
 		return IosDevice{}, err
 	}
 	if len(list) == 0 {
-		return IosDevice{}, errors.New("could not find any iOS device on this host")
+		return IosDevice{}, errors.New("no iOS devices are connected to this host")
 	}
 	if udid == "" {
 		log.Debugf("no udid specified, using '%s'", list[0].SerialNumber)

screencapture/messageprocessor.go

@@ -50,7 +50,7 @@ func NewMessageProcessorWithClockBuilder(usbWriter UsbWriter, stopSignal chan in
 func (mp *MessageProcessor) ReceiveData(data []byte) {
 	switch binary.LittleEndian.Uint32(data) {
 	case packet.PingPacketMagic:
-		log.Debug("initial ping received, sending ping back")
+		log.Info("AudioVideo-Stream has started")
 		mp.usbWriter.WriteDataToUsb(packet.NewPingPacketAsBytes())
 		return
 	case packet.SyncPacketMagic:

screencapture/usbadapter.go

@@ -42,29 +42,25 @@ func (usa *UsbAdapter) StartReading(device IosDevice, receiver UsbDataReceiver,
 		return errors.New("Could not retrieve config")
 	}
 
-	err = sendQTConfigControlRequest(usbDevice)
+	sendQTConfigControlRequest(usbDevice)
 
-	if err != nil {
-		log.Error("Error disabling config", err)
-	}
-
-	log.Infof("QT Config is active: %s", config.String())
+	log.Debugf("QT Config is active: %s", config.String())
 
 	val, err := usbDevice.Control(0x02, 0x01, 0, 0x86, make([]byte, 0))
 	if err != nil {
-		log.Warn("failed control", err)
+		log.Debug("failed control", err)
 	}
-	log.Infof("Clear Feature RC: %d", val)
+	log.Debugf("Clear Feature RC: %d", val)
 
 	val, err = usbDevice.Control(0x02, 0x01, 0, 0x05, make([]byte, 0))
 	if err != nil {
-		log.Warn("failed control", err)
+		log.Debug("failed control", err)
 	}
-	log.Infof("Clear Feature RC: %d", val)
+	log.Debugf("Clear Feature RC: %d", val)
 
 	iface, err := grabQuickTimeInterface(config)
 	if err != nil {
-		log.Error("Couldnt get Quicktime Interface")
+		log.Debug("could not get Quicktime Interface")
 		return err
 	}
 	log.Debugf("Got QT iface:%s", iface.String())
@@ -98,7 +94,7 @@ func (usa *UsbAdapter) StartReading(device IosDevice, receiver UsbDataReceiver,
 		return err
 	}
 	log.Debug("Endpoint claimed")
-
+	log.Infof("Device '%s' USB connection ready", device.SerialNumber)
 	go func() {
 
 		frameExtractor := NewLengthFieldBasedFrameExtractor()
@@ -128,10 +124,8 @@ func (usa *UsbAdapter) StartReading(device IosDevice, receiver UsbDataReceiver,
 	log.Info("Closing usb interface")
 	iface.Close()
 
-	err = sendQTDisableConfigControlRequest(usbDevice)
-	if err != nil {
-		log.Error("Error sending disable control request", err)
-	}
+	sendQTDisableConfigControlRequest(usbDevice)
+
 	return nil
 }