Merge pull request #58 from Dewberry/feature/logging

.github/workflows/e2e-tests.yml

@@ -23,6 +23,9 @@ jobs:
           echo STORAGE_BUCKET='api-storage' >> .env
           echo STORAGE_METADATA_DIR='metadata' >> .env
           echo STORAGE_RESULTS_DIR='results' >> .env
+          echo STORAGE_LOGS_DIR='logs' >> .env
+
+          echo LOCAL_LOGS_DIR='../.data/logs' >> .env
 
           echo MINIO_ACCESS_KEY_ID=user >> .env
           echo MINIO_SECRET_ACCESS_KEY=password >> .env
@@ -44,7 +47,7 @@ jobs:
           ./build.sh &
 
       - name: Build the docker-compose stack
-        run: docker-compose build -d
+        run: docker-compose build
 
       - name: Create network
         run: docker network create process_api_net
@@ -63,7 +66,31 @@ jobs:
           minio/mc:RELEASE.2023-08-18T21-57-55Z
           -c "mc alias set myminio http://minio:9000 \$MINIO_ROOT_USER \$MINIO_ROOT_PASSWORD && mc mb myminio/\${STORAGE_BUCKET}"
 
+      - name: Wait for API server to be ready
+        run: |
+          attempts=0
+          max_attempts=12  # This will wait for 2 minutes (10 seconds * 12)
+          while true; do
+            if curl -s http://localhost:5050; then
+              echo "API server is ready!"
+              break
+            fi
+            attempts=$((attempts+1))
+            if [ $attempts -eq $max_attempts ]; then
+              echo "Max attempts reached. Exiting..."
+              exit 1
+            fi
+            echo "Waiting for API server to be ready. Attempt: $attempts"
+            sleep 10
+          done
+
       - name: Run newman tests
         run: >
           docker run --network="host" -v /home/runner/work/process-api/process-api/tests/e2e:/etc/newman/ postman/newman:5.3.1-alpine run tests.postman_collection.json
           --env-var "url=localhost:5050" --reporters cli --bail --color on
+
+      ## Uncomment to print logs for debugging
+      # - name: Display docker-compose logs
+      #   run: docker-compose logs
+      #   if: always()
+

api/Dockerfile

@@ -1,15 +1,15 @@
 # -------------------------------
 FROM golang:1.19.12 AS dev
 
-RUN go install github.com/swaggo/swag/cmd/swag@v1.8.12
+# RUN go install github.com/swaggo/swag/cmd/swag@v1.8.12
 
 # Hot-Reloader
 RUN go install github.com/githubnemo/CompileDaemon@v1.4.0
 
 COPY ./ /app
 WORKDIR /app
 
-RUN swag init && go build main.go
+# RUN swag init && go build main.go
 
 ENTRYPOINT ["CompileDaemon", "--build=go build main.go", "--command=./main"]
 # -------------------------------

api/go.mod

@@ -9,6 +9,7 @@ require (
 	github.com/joho/godotenv v1.5.1
 	github.com/labstack/echo/v4 v4.10.2
 	github.com/labstack/gommon v0.4.0
+	github.com/sirupsen/logrus v1.7.0
 	github.com/swaggo/echo-swagger v1.3.5
 	github.com/swaggo/swag v1.8.1
 	gopkg.in/yaml.v3 v3.0.1

api/go.sum

@@ -104,11 +104,14 @@ github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZb
 github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
 github.com/russross/blackfriday/v2 v2.0.1/go.mod h1:+Rmxgy9KzJVeS9/2gXHxylqXiyQDYRxCVz55jmeOWTM=
 github.com/shurcooL/sanitized_anchor_name v1.0.0/go.mod h1:1NzhyTcUVG4SuEtjjoZeVRXNmyL/1OwPU0+IJeTBvfc=
+github.com/sirupsen/logrus v1.7.0 h1:ShrD1U9pZB12TX0cVy0DtePoCH97K8EtX+mg7ZARUtM=
+github.com/sirupsen/logrus v1.7.0/go.mod h1:yWOB1SBYBC5VeMP7gHvWumXLIWorT60ONWic61uBYv0=
 github.com/smartystreets/assertions v0.0.0-20180927180507-b2de0cb4f26d/go.mod h1:OnSkiWE9lh6wB0YB77sQom3nweQdgAjqCqsofrRNTgc=
 github.com/smartystreets/goconvey v1.6.4/go.mod h1:syvi0/a8iFYH4r/RixwvyeAJjdLS9QV7WQ/tjFTllLA=
 github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
 github.com/stretchr/objx v0.4.0/go.mod h1:YvHI0jy2hoMjB+UWwv71VJQ9isScKT/TqJzVSSt89Yw=
 github.com/stretchr/objx v0.5.0/go.mod h1:Yh+to48EsGEfYuaHDzXPcE3xhTkx73EhmCGUpEOglKo=
+github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs=
 github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI=
 github.com/stretchr/testify v1.6.1/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
 github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
@@ -170,6 +173,7 @@ golang.org/x/sync v0.0.0-20210220032951-036812b2e83c/go.mod h1:RxMgew5VJxzue5/jJ
 golang.org/x/sync v0.0.0-20220722155255-886fb9371eb4/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
 golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
 golang.org/x/sys v0.0.0-20190412213103-97732733099d/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
+golang.org/x/sys v0.0.0-20191026070338-33540a1f6037/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20200930185726-fdedc70b468f/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20201119102817-f84b799fce68/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20210119212857-b64e53b001e4/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=

api/handlers/config.go

@@ -8,6 +8,7 @@ import (
 	"fmt"
 	"io"
 	"os"
+	"strings"
 	"text/template"
 
 	"github.com/aws/aws-sdk-go/aws"
@@ -75,7 +76,9 @@ func NewRESTHander(pluginsDir string, dbPath string) *RESTHandler {
 
 	// Read all the html templates
 	funcMap := template.FuncMap{
-		"prettyPrint": prettyPrint, // to pretty pring JSONs for results and metadata
+		"prettyPrint": prettyPrint, // to pretty print JSONs for results and metadata
+		"lower":       strings.ToLower,
+		"upper":       strings.ToUpper,
 	}
 
 	config.T = Template{
@@ -93,6 +96,16 @@ func NewRESTHander(pluginsDir string, dbPath string) *RESTHandler {
 	}
 	config.StorageSvc = stSvc
 
+	// Create local logs directory if not exist
+	localLogsDir, exist := os.LookupEnv("LOCAL_LOGS_DIR")
+	if !exist {
+		log.Fatal("env variable LOCAL_LOGS_DIR not set")
+	}
+	err = os.MkdirAll(localLogsDir, 0755)
+	if err != nil {
+		log.Fatalf(err.Error())
+	}
+
 	// Setup Active Jobs that will store all jobs currently in process
 	ac := jobs.ActiveJobs{}
 	ac.Jobs = make(map[string]*jobs.Job)

api/handlers/handlers.go

@@ -21,6 +21,7 @@ import (
 	"github.com/google/uuid"
 	"github.com/labstack/echo/v4"
 	"github.com/labstack/gommon/log"
+	"github.com/sirupsen/logrus"
 )
 
 // base error
@@ -351,8 +352,7 @@ func (rh *RESTHandler) Execution(c echo.Context) error {
 			var outputs interface{}
 
 			if p.Outputs != nil {
-				// outputs, err = jobs.FetchResults(rh.StorageSvc, j.JobID())
-				outputs, err = jobs.FetchResults(rh.DB, j.JobID())
+				outputs, err = jobs.FetchResults(rh.StorageSvc, j.JobID())
 				if err != nil {
 					resp.Message = "error fetching results. Error: " + err.Error()
 					return c.JSON(http.StatusInternalServerError, resp)
@@ -455,11 +455,10 @@ func (rh *RESTHandler) JobResultsHandler(c echo.Context) error {
 
 		switch jRcrd.Status {
 		case jobs.SUCCESSFUL:
-			// outputs, err := jobs.FetchResults(rh.StorageSvc, jRcrd.JobID)
-			outputs, err := jobs.FetchResults(rh.DB, jRcrd.JobID)
+			outputs, err := jobs.FetchResults(rh.StorageSvc, jRcrd.JobID)
 			if err != nil {
 				if err.Error() == "not found" {
-					output := errResponse{HTTPStatus: http.StatusNotFound, Message: "results not available, resource might have expired"}
+					output := errResponse{HTTPStatus: http.StatusNotFound, Message: "results not available"}
 					return prepareResponse(c, http.StatusNotFound, "error", output)
 				}
 				output := errResponse{HTTPStatus: http.StatusInternalServerError, Message: err.Error()}
@@ -548,28 +547,28 @@ func (rh *RESTHandler) JobLogsHandler(c echo.Context) error {
 		return err
 	}
 
-	var logs jobs.JobLogs
-	var errLogs error
+	var pid string
 
 	if job, ok := rh.ActiveJobs.Jobs[jobID]; ok { // ActiveJobs hit
-		if (*job).CurrentStatus() == jobs.ACCEPTED {
-			output := errResponse{HTTPStatus: http.StatusBadRequest, Message: "job not yet started"}
-			return prepareResponse(c, http.StatusBadRequest, "error", output)
+		err = (*job).UpdateContainerLogs()
+		if err != nil {
+			output := errResponse{HTTPStatus: http.StatusInternalServerError, Message: "error while updating container logs: " + err.Error()}
+			return prepareResponse(c, http.StatusInternalServerError, "error", output)
 		}
-		logs, errLogs = (*job).Logs()
-	} else if ok := rh.DB.CheckJobExist(jobID); ok { // db hit
-		logs, errLogs = rh.DB.GetLogs(jobID)
+		pid = (*job).ProcessID()
+	} else if jRcrd, ok := rh.DB.GetJob(jobID); ok { // db hit
+		pid = jRcrd.ProcessID
 	} else { // miss
 		output := errResponse{HTTPStatus: http.StatusNotFound, Message: "jobID not found"}
 		return prepareResponse(c, http.StatusNotFound, "error", output)
 	}
 
-	if errLogs != nil {
-		output := errResponse{HTTPStatus: http.StatusInternalServerError, Message: "error while fetching logs: " + errLogs.Error()}
+	logs, err := jobs.FetchLogs(rh.StorageSvc, jobID, pid, false)
+	if err != nil {
+		output := errResponse{HTTPStatus: http.StatusInternalServerError, Message: "error while fetching logs: " + err.Error()}
 		return prepareResponse(c, http.StatusInternalServerError, "error", output)
 	}
 
-	logs.Prettify()
 	return prepareResponse(c, http.StatusOK, "jobLogs", logs)
 
 }
@@ -664,11 +663,11 @@ func (rh *RESTHandler) JobStatusUpdateHandler(c echo.Context) error {
 		default:
 			return c.JSON(http.StatusBadRequest, fmt.Sprintf("status not valid, valid options are: %s, %s, %s, %s, %s", jobs.ACCEPTED, jobs.RUNNING, jobs.DISMISSED, jobs.FAILED, jobs.SUCCESSFUL))
 		}
-		(*sm.Job).NewMessage(fmt.Sprintf("Status update received: %s", sm.Status))
+		(*sm.Job).LogMessage(fmt.Sprintf("Status update received: %s.", sm.Status), logrus.InfoLevel)
 		rh.MessageQueue.StatusChan <- sm
 		return c.JSON(http.StatusAccepted, "status update received")
 	} else if ok := rh.DB.CheckJobExist(jobID); ok { // db hit
-		log.Warnf("Status update received for inactive job: %s", jobID)
+		log.Infof("Status update received for inactive job: %s", jobID)
 		// returning Accepted here so that callers do not retry
 		return c.JSON(http.StatusAccepted, "job not an active job")
 	} else {