TID #007 Logging: Create a logger for both the app and the machine

catfeeder-app/src/catfeeder/app.py

@@ -1,9 +1,10 @@
 """
 An app to feed the cats
 """
-import toga
-import requests
 import json
+import requests
+import toga
+import utils
 from toga.style import Pack
 from toga.style.pack import COLUMN, ROW
 
@@ -13,6 +14,7 @@
 RECIEVE_ALL_TIMES = BASE_URL + "/feedingTimes"
 
 feeding_times = []
+logger = utils.Applogger('cat-app')
 
 class CatFeeder(toga.App):
     # TODO: Come up with better variable names
@@ -71,17 +73,17 @@ def startup(self):
     ###
     def addTime(self, widget):
         if self.hour_input.value == "":
-            print("Hour time is missing")
+            self.error_label.text = "Missing time for hour"
             return
         if self.min_input.value == "":
-            print("Minute time is missing")
+            self.error_label.text = "Missing time for minute"
             return
 
         self.send_butt.enabled = True
         feeding_times.append((self.hour_input.value,self.min_input.value))
-        time = self.prettyTime(feeding_times[len(feeding_times) - 1][0], feeding_times[len(feeding_times) - 1][1])
+        time = utils.PrettyTime(feeding_times[len(feeding_times) - 1])
         self.time_table.data.insert(0, time)
-        print("New Time:", feeding_times[len(feeding_times) - 1])
+        logger.info("New Time: " + str(time))
         self.error_label.text = ""
 
     ###
@@ -97,7 +99,7 @@ def clearTable(self, widget):
     ###
     def sendFeedingTime(self, widget):
         if len(feeding_times) == 0:
-            print("No times given")
+            self.error_label.text = "No feeding times present"
             return
 
         send_feeding_times = []
@@ -116,48 +118,44 @@ def sendFeedingTime(self, widget):
                 data = str(json.dumps(send_feeding_times))
             )
         except OSError as err:
-            print("OSError: Uh oh! Looks like you are in trouble...", err)
-            self.error_label.text = "Error on communicating with machine"
+            logger.error("Uh oh! Looks like trouble found you: error(" + utils.StrOSError(err) + ")")
+            self.error_label.text = "Error on communicating with machine: error(" + utils.StrOSError(err) + ")"
             return
 
         resp = req.text
-        print("Sent feeding time:", resp)
+        logger.info("Sent feeding time:" + str(resp))
         self.error_label.text = ""
 
     ###
     # @brief:   Get any existing feeding time payload
     ###
     def getFeedingTimes(self, widget):
-        feeding_times = []
-        self.time_table.data.clear()
-
         try:
             req = requests.get(url = RECIEVE_ALL_TIMES)
             if req == None:
-                print("Uh oh! Things not looking good")
+                logger.error("Uh oh! Received invalid feeding times: Feeding-Time(" + req + ")")
                 self.error_label.text = "Received invalid feeding times:", req
                 return
             if req.status_code != 200:
-                print("Uh oh! Not success:", req.status_code)
-                self.error_label.text = "Failed to recieve request:" + str(req.status_code)
+                logger.error("Uh oh! Request unsuccessful: HTTP(" + str(req.status_code) + ")")
+                self.error_label.text = "Failed to receive request: HTTP(" + str(req.status_code) + ")"
                 return
 
         except OSError as err:
-            print("OSError: Uh oh! Looks like you are in trouble...", err)
-            self.error_label.text = "Error on communicating with machine"
+            logger.error("Uh oh! Looks like trouble found you: error(" + utils.StrOSError(err) + ")")
+            self.error_label.text = "Error on communicating with machine: error(" + utils.StrOSError(err) + ")"
             return
 
+        feeding_times = []
+        self.time_table.data.clear()
         resp = req.json()
         for i in range(len(resp)):
             feeding_times.append((resp[i]['hour'],resp[i]['minute']))
-            time = self.prettyTime(feeding_times[len(feeding_times) - 1][0], feeding_times[len(feeding_times) - 1][1])
+            time = utils.PrettyTime(feeding_times[len(feeding_times) - 1])
             self.time_table.data.insert(i, time)
-        print("Recieved feeding times:", feeding_times)
+        logger.info("Received feeding times:" + str(feeding_times))
         self.send_butt.enabled = True
         self.error_label.text = ""
 
-    def prettyTime(self, hour, minute):
-        return str(hour) + ":" + (str(minute) if int(minute) > 9 else "0" + str(minute))
-
 def main():
     return CatFeeder()

catfeeder-app/utils.py

@@ -0,0 +1,42 @@
+import logging
+
+###
+# @brief:   Create new logging object with the identity of `name`
+#
+# @arg:     name - The name to give the identity of the log
+#
+# @return:  Logger object
+###
+def Applogger(name):
+    logging.basicConfig(level=logging.INFO,
+                        filename='/tmp/cat-feeder.log',
+                        format='%(asctime)s %(name)s - %(message)s',
+                        datefmt='%Y/%m/%d %H:%M:%S'
+                       )
+
+    logger = logging.getLogger(name)
+
+    return logger
+
+###
+# @brief:   Turn the feeding time input to the time format
+#
+# @arg:     feeding_time - Array holding the hour and minute
+#
+# @return:  String formated time
+###
+def PrettyTime(feeding_times):
+    hour = feeding_times[0]
+    minute = feeding_times[1]
+
+    return str(hour) + ":" + (str(minute) if int(minute) > 9 else "0" + str(minute))
+
+###
+# @brief:   Parse the OS error to return the error message
+#
+# @arg:     err - OSError from try-except
+#
+# @return:  String formatted error message
+###
+def StrOSError(err):
+    return str(err.args[0].reason)[str(err.args[0].reason).find(":") + 2:]

catfeeder-machine/golog.go

@@ -0,0 +1,78 @@
+package main
+
+import (
+    "os"
+    "strings"
+    "sync"
+    "time"
+)
+
+type Golog struct {
+    Lock        sync.Mutex
+    Fpath       *os.File
+    Prefix      string
+}
+
+const LogFilename string = "/tmp/cat-feeder.log"
+
+/**
+ * @brief:  Checks to see if the log file is present from a previous
+ *          execution. If true, roll over log with timestamp.
+ *
+ * @return: nil on success, else error
+ **/
+func InitGolog() error {
+    finfo, err := os.Stat(LogFilename)
+    if err == nil {
+        path := strings.Split(LogFilename, finfo.Name())[0]
+        err = os.Rename(
+            LogFilename,
+            path + time.Now().Format("20060102T150405") + "-" + finfo.Name(),
+        )
+        if err != nil {
+            return err
+        }
+    }
+
+    return err
+}
+
+/**
+ * @brief:  Opens and creates a log file. If no errors opening/creating,
+ *          then create a Golog with prefix and file pointer
+ *
+ * @arg:    prefix - String to prepend to the log message
+ *
+ * @return: New logger, nil if error
+ **/
+func OpenGolog(prefix string) *Golog {
+    fpath, err := os.OpenFile(LogFilename, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0666)
+
+    if err != nil {
+        return nil
+    }
+
+    return &Golog{
+        Prefix: prefix,
+        Fpath: fpath,
+    }
+}
+
+/**
+ * @brief:  Write log message to the log file. Log message contains:
+ *          - Timestamp
+ *          - Prefix
+ *          - Message
+ *
+ * @arg:    msg - Message to write to log file
+ *
+ * @return: int - How many bytes were written
+ *          error - Errors while writing
+ **/
+func (gl *Golog) Println(msg string) (int, error) {
+    gl.Lock.Lock()
+    defer gl.Lock.Unlock()
+
+    output := []byte(time.Now().Format("2006/01/02 15:04:05") + " " + gl.Prefix + " - " + msg + "\n")
+    return gl.Fpath.Write(output)
+}

catfeeder-machine/main.go

@@ -37,18 +37,27 @@ func TimeToFeedCat() bool {
     return false
 }
 
+func init() {
+    if err := InitGolog(); err != nil {
+        fmt.Println("Failed to initialize log rollover:", err)
+    }
+}
+
 func main() {
+    /* Open log file */
+    cat_log := OpenGolog("cat-manager")
+
     /* Run REST API */
     go HandleRequests()
 
     /* Monitor the feeding time */
     go func() {
         for {
             if TimeToFeedCat() && !has_been_fed {
-                fmt.Println("Time to feed cats")
+                cat_log.Println("Time to feed cats")
                 has_been_fed = true
             } else if !TimeToFeedCat() {
-                fmt.Println("Not time to feed cats")
+                cat_log.Println("Not time to feed cats")
                 has_been_fed = false
             }
             time.Sleep(10 * time.Second)

catfeeder-machine/rest-api.go

@@ -4,18 +4,23 @@ import (
     "fmt"
     "io/ioutil"
     "encoding/json"
-    "log"
     "net/http"
 
     "github.com/gorilla/mux"
 )
 
-func PrintFeedingTimes(feeding_times []FeedingTimes) {
+var rest_log *Golog
+
+func FeedingTimeStr(feeding_times []FeedingTimes) string {
+    ft_str := ""
+
     for _, ft := range feeding_times {
-        fmt.Printf("{ ID(%s) -- Hour(%d) -- Minute(%d) } ",
-            ft.ID, ft.Hour, ft.Minute)
+        ft_str += fmt.Sprintf(" { ID(%s) -- Hour(%d) -- Minute(%d) } ",
+            ft.ID, ft.Hour, ft.Minute,
+        )
     }
-    fmt.Println()
+
+    return ft_str
 }
 
 /**
@@ -32,8 +37,7 @@ func CreateNewFeedTime(w http.ResponseWriter, r *http.Request) {
     json.NewEncoder(w).Encode(feeding_times)
     mut.Unlock()
 
-    fmt.Print("Recieved feeding times: ")
-    PrintFeedingTimes(ft)
+    rest_log.Println("Received feeding times:" + FeedingTimeStr(ft))
 }
 
 /**
@@ -47,9 +51,7 @@ func ReturnSingleFeedingTime(w http.ResponseWriter, r *http.Request) {
     for _, ft := range feeding_times {
         if ft.ID == key {
             json.NewEncoder(w).Encode(ft)
-            fmt.Print("Sending feeding time: ")
-            feeding := []FeedingTimes{ft}
-            PrintFeedingTimes(feeding)
+            rest_log.Println("Sending feeding time:" + FeedingTimeStr([]FeedingTimes{ft}))
             break
         }
     }
@@ -62,8 +64,7 @@ func ReturnSingleFeedingTime(w http.ResponseWriter, r *http.Request) {
 func ReturnAllFeedingTimes(w http.ResponseWriter, r *http.Request) {
     mut.Lock()
     json.NewEncoder(w).Encode(feeding_times)
-    fmt.Print("Sending feeding times: ")
-    PrintFeedingTimes(feeding_times)
+    rest_log.Println("Sending feeding times:" + FeedingTimeStr(feeding_times))
     mut.Unlock()
 }
 
@@ -82,10 +83,14 @@ func HomePage(w http.ResponseWriter, r *http.Request) {
  * @brief:  Handle to monitor all the CRUD methods.
  **/
 func HandleRequests() {
+    rest_log = OpenGolog("rest-api")
+
     myRouter := mux.NewRouter().StrictSlash(true)
     myRouter.HandleFunc("/", HomePage)
     myRouter.HandleFunc("/feedingTime", CreateNewFeedTime).Methods("POST")
     myRouter.HandleFunc("/feedingTimes", ReturnAllFeedingTimes).Methods("GET")
     myRouter.HandleFunc("/feedingTime/{id}", ReturnSingleFeedingTime).Methods("GET")
-    log.Fatal(http.ListenAndServe(":6969", myRouter))
+
+    rest_log.Println("Listening on 127.0.0.1:6969")
+    rest_log.Println(http.ListenAndServe(":6969", myRouter).Error())
 }