Fixed behavior of multi-step builds.

* Output from the main strawboss executable is properly directed to stdout
  and stderr.
* Added threshold logging to strawboss core functions.
* Fixed a bug in the way dependent steps were detected and executed.
  The logic for checking if prior steps had already been executed was only
  executed once when the initial step was prepared, not for any of the
  dependent steps. This logic has been moved into the main work block for
  executing steps.
* Renamed `initiateRun` to `run` and  `runStep` to `doRun` to be more accurate.
* Dependent steps get their owng, independent copy of the workspace.
* Updated the test project to provide a test target.

src/main/nim/strawboss.nim

@@ -8,8 +8,8 @@ let SB_VER = "0.2.0"
 
 proc logProcOutput*(outMsg, errMsg: TaintedString, cmd: string) =
   let prefix = if cmd != nil: cmd else: ""
-  if outMsg != nil: echo prefix & "(stdout): " & outMsg
+  if outMsg != nil: stdout.writeLine prefix & outMsg
-  if errMsg != nil: echo prefix & "(stderr): " & errMsg
+  if errMsg != nil: stderr.writeLine prefix & errMsg
 
 when isMainModule:
 
@@ -51,7 +51,7 @@ Options
 
       if req.workspaceDir.isNilOrEmpty: req.workspaceDir = mkdtemp()
 
-      let status = core.initiateRun(cfg, req, logProcOutput)
+      let status = core.run(cfg, req, logProcOutput)
       if status.state == BuildState.failed: raiseEx status.details
       echo "strawboss: build passed."
     except:

src/main/nim/strawbosspkg/configuration.nim

@@ -1,4 +1,4 @@
-import cliutils, logging, json, os, sequtils, strtabs, tables, times, uuids
+import cliutils, logging, json, os, sequtils, strtabs, strutils, tables, times, uuids
 
 from langutils import sameContents
 from typeinfo import toAny
@@ -52,6 +52,7 @@ type
     authSecret*: string
     filePath*: string
     debug*: bool
+    logLevel*: Level
     pathToExe*: string
     projects*: seq[ProjectDef]
     pwdCost*: int8
@@ -79,6 +80,7 @@ proc `==`*(a, b: StrawBossConfig): bool =
     a.authSecret == b.authSecret and
     a.pwdCost == b.pwdCost and
     a.maintenancePeriod == b.maintenancePeriod and
+    a.logLevel == b.logLevel and
     sameContents(a.users, b.users) and
     sameContents(a.projects, b.projects)
 
@@ -111,6 +113,10 @@ proc getOrFail(n: JsonNode, key: string, objName: string = ""): JsonNode =
 
 # Configuration parsing code
 
+proc parseLogLevel*(level: string): Level =
+  let lvlStr = "lvl" & toUpper(level[0]) & level[1..^1]
+  result = parseEnum[Level](lvlStr)
+
 proc parseProjectDef*(pJson: JsonNode): ProjectDef =
   var envVars = newStringTable(modeCaseSensitive)
   for k, v in pJson.getIfExists("envVars").getFields: envVars[k] = v.getStr("")
@@ -137,6 +143,7 @@ proc parseStrawBossConfig*(jsonCfg: JsonNode): StrawBossConfig =
     pwdCost: int8(jsonCfg.getOrFail("pwdCost", "strawboss config").getNum),
     projects: jsonCfg.getIfExists("projects").getElems.mapIt(parseProjectDef(it)),
     maintenancePeriod: int(jsonCfg.getIfExists("maintenancePeriod").getNum(10000)),
+    logLevel: parseLogLevel(jsonCfg.getIfExists("logLevel").getStr("lvlInfo")),
     users: users)
 
 
@@ -271,6 +278,7 @@ proc `%`*(cfg: StrawBossConfig): JsonNode =
     "projects": %cfg.projects,
     "pwdCost": cfg.pwdCost,
     "maintenancePeriod": cfg.maintenancePeriod,
+    "logLevel": cfg.logLevel,
     "users": %cfg.users }
 
 proc `%`*(run: Run): JsonNode =

src/main/nim/strawbosspkg/core.nim

@@ -8,11 +8,11 @@ from algorithm import sorted
 
 type
   Workspace = ref object      ## Data needed by internal build process
-    artifactsDir*: string     ## absolute path to the directory for this version
     buildDataDir*: string     ## absolute path to the global build data directory for this project
     buildRef*: string         ## git-style commit reference to the revision we are building
     dir*: string              ## absolute path to the working directory
     env*: StringTableRef      ## environment variables for all build processes
+    logLevel*: Level          ## log level for output messages
     openedFiles*: seq[File]   ## all files that we have opened that need to be closed
     outputHandler*: HandleProcMsgCB ## handler for process output
     project*: ProjectConfig   ## the project configuration
@@ -29,6 +29,27 @@ type
 
   NotFoundException = object of Exception
 
+proc newCopy(w: Workspace): Workspace =
+  var newEnv: StringTableRef = newStringTable()
+  newEnv[] = w.env[]
+
+  result = Workspace(
+    buildDataDir: w.buildDataDir,
+    buildRef: w.buildRef,
+    dir: w.dir,
+    env: newEnv,
+    logLevel: w.logLevel,
+    # workspaces are only responsible for files they have actually openend
+    openedFiles: @[],
+    outputHandler: w.outputHandler,
+    project: w.project,
+    projectDef: w.projectDef,
+    runRequest: w.runRequest,
+    status: w.status,
+    step: w.step,
+    version: w.version)
+
+# Logging wrappers around
 # Utility methods for Workspace activities
 proc sendStatusMsg(oh: HandleProcMsgCB, status: BuildStatus): void =
   if not oh.isNil:
@@ -37,14 +58,22 @@ proc sendStatusMsg(oh: HandleProcMsgCB, status: BuildStatus): void =
 proc sendMsg(w: Workspace, msg: TaintedString): void =
   w.outputHandler.sendMsg(msg, nil, "strawboss")
 
+proc sendMsg(w: Workspace, l: Level, msg: TaintedString): void =
+  if l >= w.logLevel: w.sendMsg(msg)
+
 proc sendErrMsg(w: Workspace, msg: TaintedString): void =
   w.outputHandler.sendMsg(nil, msg, "strawboss")
 
-proc resolveEnvVars(line: string, env: StringTableRef): string =
+proc sendErrMsg(w: Workspace, l: Level, msg: TaintedString): void =
+  if l >= w.logLevel: w.sendErrMsg(msg)
+
+proc resolveEnvVars(wksp: Workspace, line: string): string =
   result = line
   for found in line.findAll(re"\$\w+|\$\{[^}]+\}"):
     let key = if found[1] == '{': found[2..^2] else: found[1..^1]
-    if env.hasKey(key): result = result.replace(found, env[key])
+    if wksp.env.hasKey(key): result = result.replace(found, wksp.env[key])
+  wksp.sendMsg(lvlDebug, "Variable substitution: \n\t" & line &
+    "\n\t" & result)
 
 proc publishStatus(wksp: Workspace, state: BuildState, details: string): void =
   ## Update the status for a Workspace and publish this status to the
@@ -66,8 +95,8 @@ proc publishStatus(wksp: Workspace, state: BuildState, details: string): void =
     # "master" or something), then let's also save our status under that name.
     # We're probably overwriting a prior status, but that's OK.
     if wksp.runRequest.buildRef != wksp.version:
-      writeFile(wksp.buildDataDir & "/status/" & wksp.step.name & "/" &
+      writeFile(stepStatusDir & "/" & wksp.runRequest.buildRef & ".json",
-        wksp.runRequest.buildRef & ".json", $wksp.status)
+                $wksp.status)
 
   wksp.outputHandler.sendStatusMsg(wksp.status)
 
@@ -196,17 +225,23 @@ proc getProjectConfig*(cfg: StrawBossConfig,
 # Internal working methods.
 proc setupProject(wksp: Workspace) =
 
+  wksp.sendMsg(lvlDebug, "Setting up project.")
+
   # Clone the project into the $temp directory
-  let cloneResult = exec("git", ".",
+  let cloneArgs = ["clone", wksp.projectDef.repo, wksp.dir]
-    ["clone", wksp.projectDef.repo, wksp.dir],
+  wksp.sendMsg(lvlDebug, "git " & $cloneArgs)
-    wksp.env, {poUsePath}, wksp.outputHandler)
+
+  let cloneResult = exec("git", ".", cloneArgs, wksp.env, {poUsePath},
+    wksp.outputHandler)
 
   if cloneResult != 0:
     raiseEx "unable to clone repo for '" & wksp.projectDef.name & "'"
 
   # Checkout the requested ref
-  let checkoutResult = exec("git", wksp.dir,
+  let checkoutArgs = ["checkout", wksp.buildRef]
-    ["checkout", wksp.buildRef],
+  wksp.sendMsg(lvlDebug, "git " & $checkoutArgs)
+
+  let checkoutResult = exec("git", wksp.dir, checkoutArgs,
     wksp.env, {poUsePath}, wksp.outputHandler)
 
   if checkoutResult != 0:
@@ -215,6 +250,7 @@ proc setupProject(wksp: Workspace) =
 
   # Find the strawboss project configuration
   let projCfgFile = wksp.dir & "/" & wksp.projectDef.cfgFilePath
+  wksp.sendMsg(lvlDebug, "Looking for project configuration at '" & projCfgFile & "'")
   if not existsFile(projCfgFile):
     raiseEx "Cannot find strawboss project configuration in the project " &
       "repo (expected at '" & wksp.projectDef.cfgFilePath & "')."
@@ -239,16 +275,39 @@ proc setupProject(wksp: Workspace) =
   wksp.version = versionResult.output.strip
   wksp.env["VERSION"] = wksp.version
 
-proc runStep*(wksp: Workspace, step: Step) =
+proc doStep*(wksp: Workspace, step: Step): BuildStatus =
 
   ## Lower-level method to execute a given step within the context of a project
   ## workspace that is setup and configured. May be called recursively to
   ## satisfy step dependencies.
 
-  let SB_EXPECTED_VARS = ["VERSION"]
-
   wksp.step = step
 
+  let artifactsDir = wksp.buildDataDir & "/artifacts/" &
+                     step.name & "/" & wksp.version
+
+  if not existsDir(artifactsDir): createDir(artifactsDir)
+
+  # Have we tried to build this before and are we caching the results?
+  let statusFilePath = wksp.buildDataDir & "/status/" & step.name &
+    "/" & wksp.version & ".json"
+
+  if existsFile(statusFilePath) and not step.dontSkip:
+    let prevStatus = loadBuildStatus(statusFilePath)
+
+    # If we succeeded last time, no need to rebuild
+    if prevStatus.state == BuildState.complete:
+      wksp.publishStatus(BuildState.complete,
+        "Skipping step '" & step.name & "' for version '" & wksp.version &
+          "': already completed.")
+      return wksp.status
+    else:
+      wksp.sendMsg(
+        "Rebuilding failed step '" & step.name & "' for version '" &
+        wksp.version & "'.")
+
+  let SB_EXPECTED_VARS = ["VERSION"]
+
   wksp.publishStatus(BuildState.running,
     "running '" & step.name & "' for version " & wksp.version &
     " from " & wksp.buildRef)
@@ -267,26 +326,35 @@ proc runStep*(wksp: Workspace, step: Step) =
     let depStep = wksp.project.steps[dep]
 
     # Run that step (may get skipped)
-    runStep(wksp, depStep)
+    let runStatus = doStep(core.newCopy(wksp), depStep)
+
+    if not (runStatus.state == BuildState.complete):
+      raiseEx "dependent step failed: " & depStep.name
+
+    wksp.sendMsg(lvlDebug, "dependent step '" & depStep.name &
+      "'completed, resuming '" & wksp.step.name & "'")
 
     # Add the artifacts directory for the dependent step to our env so that
     # further steps can reference it via $<stepname>_DIR
     wksp.env[depStep.name & "_DIR"] = wksp.buildDataDir & "/artifacts/" &
-      "/" & dep & "/" & wksp.version
+      dep & "/" & wksp.version
 
   # Run the step command, piping in cmdInput
-  wksp.sendMsg step.name & ": starting stepCmd: " & step.stepCmd
+  let stepCmd = wksp.resolveEnvVars(step.stepCmd)
-  let cmdProc = startProcess(step.stepCmd,
+  let cmdName = if stepCmd.rfind("/") >= 0: stepCmd[(stepCmd.rfind("/") + 1)..^1]
+                else: stepCmd
+  wksp.sendMsg step.name & ": starting stepCmd: " & stepCmd
+  let cmdProc = startProcess(stepCmd,
     wksp.dir & "/" & step.workingDir, [], wksp.env, {poUsePath, poEvalCommand})
 
   let cmdInStream = inputStream(cmdProc)
 
   # Replace env variables in step cmdInput as we pipe it in
-  for line in step.cmdInput: cmdInStream.writeLine(line.resolveEnvVars(wksp.env))
+  for line in step.cmdInput: cmdInStream.writeLine(wksp.resolveEnvVars(line))
   cmdInStream.flush()
   cmdInStream.close()
   
-  let cmdResult = waitFor(cmdProc, wksp.outputHandler, step.stepCmd)
+  let cmdResult = waitFor(cmdProc, wksp.outputHandler, cmdName)
 
   if cmdResult != 0:
     raiseEx "step " & step.name & " failed: step command returned non-zero exit code"
@@ -295,22 +363,23 @@ proc runStep*(wksp: Workspace, step: Step) =
   wksp.sendMsg "artifacts: " & $step.artifacts
   if step.artifacts.len > 0:
     for a in step.artifacts:
-      let artifactPath = a.resolveEnvVars(wksp.env)
+      let artifactPath = wksp.resolveEnvVars(a)
       let artifactName = artifactPath[(artifactPath.rfind("/")+1)..^1]
       try:
         wksp.sendMsg "copy " &
           wksp.dir & "/" & step.workingDir & "/" & artifactPath & " -> " &
-          wksp.artifactsDir & "/" & artifactName
+          artifactsDir & "/" & artifactName
 
-        copyFile(wksp.dir & "/" & step.workingDir & "/" & artifactPath,
+        copyFileWithPermissions(wksp.dir & "/" & step.workingDir & "/" &
-                 wksp.artifactsDir & "/" & artifactName)
+          artifactPath, artifactsDir & "/" & artifactName)
       except:
         raiseEx "step " & step.name & " failed: unable to copy artifact " &
           artifactPath & ":\n" & getCurrentExceptionMsg()
 
   wksp.publishStatus(BuildState.complete, "")
+  result = wksp.status
 
-proc initiateRun*(cfg: StrawBossConfig, req: RunRequest,
+proc run*(cfg: StrawBossConfig, req: RunRequest,
               outputHandler: HandleProcMsgCB = nil): BuildStatus =
 
   ## Execute a RunReuest given the StrawBoss configuration. This is the main
@@ -350,13 +419,13 @@ proc initiateRun*(cfg: StrawBossConfig, req: RunRequest,
     let logFilesOH = makeProcMsgHandler(stdoutFile, stderrFile)
 
     wksp = Workspace(
-      artifactsDir: nil,
       buildDataDir: cfg.buildDataDir & "/" & projectDef.name,
       buildRef:
         if req.buildRef != nil and req.buildRef.len > 0: req.buildRef
         else: projectDef.defaultBranch,
       dir: req.workspaceDir,
       env: env,
+      logLevel: cfg.logLevel,
       openedFiles: @[stdoutFile, stderrFile],
       outputHandler: combineProcMsgHandlers(outputHandler, logFilesOH),
       project: ProjectConfig(),
@@ -382,7 +451,7 @@ proc initiateRun*(cfg: StrawBossConfig, req: RunRequest,
 
     # Update our cache of project configurations.
     # TODO: what happens if this fails?
-    copyFile(
+    copyFileWithPermissions(
       wksp.dir & "/" & wksp.projectDef.cfgFilePath,
       wksp.buildDataDir & "/configurations/" & wksp.version & ".json")
 
@@ -393,32 +462,7 @@ proc initiateRun*(cfg: StrawBossConfig, req: RunRequest,
 
     if req.forceRebuild: step.dontSkip = true
 
-    wksp.artifactsDir = wksp.buildDataDir & "/artifacts/" &
+    result = doStep(wksp, step)
-                        step.name & "/" & wksp.version
-
-    # Have we tried to build this before and are we caching the results?
-    let statusFilePath = wksp.buildDataDir & "/status/" & step.name &
-      "/" & wksp.version & ".json"
-
-    if existsFile(statusFilePath) and not step.dontSkip:
-      let prevStatus = loadBuildStatus(statusFilePath)
-
-      # If we succeeded last time, no need to rebuild
-      if prevStatus.state == BuildState.complete:
-        wksp.publishStatus(BuildState.complete,
-          "Skipping step '" & step.name & "' for version '" & wksp.version &
-            "': already completed.")
-        return prevStatus
-      else:
-        wksp.sendMsg(
-          "Rebuilding failed step '" & step.name & "' for version '" &
-          wksp.version & "'.")
-
-    if not existsDir(wksp.artifactsDir): createDir(wksp.artifactsDir)
-
-    runStep(wksp, step)
-
-    result = wksp.status
 
   except:
     when not defined(release): echo getCurrentException().getStackTrace()
@@ -433,6 +477,7 @@ proc initiateRun*(cfg: StrawBossConfig, req: RunRequest,
 
   finally:
     if wksp != nil:
+      # Close open files 
       for f in wksp.openedFiles:
         try: close(f)
         except: discard ""

src/main/nim/strawbosspkg/server.nim

@@ -273,13 +273,15 @@ proc start*(cfg: StrawBossConfig): void =
       # TODO: instead of immediately spawning a worker, add the request to a
       # queue to be picked up by a worker. Allows capping the number of worker
       # prcesses, distributing, etc.
-      let (status, worker) = spawnWorker(cfg, runRequest)
+      try:
-      workers.add(worker)
+        let (status, worker) = spawnWorker(cfg, runRequest)
+        workers.add(worker)
 
-      resp($Run(
+        resp($Run(
-        id: runRequest.runId,
+          id: runRequest.runId,
-        request: runRequest,
+          request: runRequest,
-        status: status), JSON)
+          status: status), JSON)
+      except: resp(Http404, makeJsonResp(Http404, getCurrentExceptionMsg()), JSON)
 
     post "/service/debug/stop":
       if not cfg.debug: resp(Http404, makeJsonResp(Http404), JSON)

src/test/nim/functional/tcore.nim

@@ -5,3 +5,15 @@ from langutils import sameContents
 import ../testutil
 import ../../../main/nim/strawbosspkg/configuration
 
+let cfgFilePath = "src/test/json/strawboss.config.json"
+let cfg = loadStrawBossConfig(cfgFilePath)
+let TIMEOUT = 2.minutes
+
+suite "strawboss core":
+
+  # Suite setup: extract test project
+  let testProjTempDir = mkdir()
+  let testProjTarFile = newTarFile("src/test/test-project.tar.gz:)
+  let testProjName = "test-project"
+  testProjTarFile.extract(testProjTempDir)
+

src/test/nim/unit/tconfiguration.nim

@@ -1,4 +1,4 @@
-import json, strtabs, tables, unittest, uuids
+import json, strtabs, times, tables, unittest, uuids
 
 from langutils import sameContents
 import ../../../main/nim/strawbosspkg/configuration
@@ -21,11 +21,12 @@ suite "load and save configuration objects":
 
   test "parseRunRequest":
     let rr1 = RunRequest(
-      id: genUUID(),
+      runId: genUUID(),
       projectName: testProjDef.name,
       stepName: "build",
       buildRef: "master",
       workspaceDir: "/no-real/dir",
+      timestamp: getLocalTime(getTime()),
       forceRebuild: true)
 
     let rrStr = $rr1
@@ -143,5 +144,5 @@ suite "load and save configuration objects":
 
     check:
       st.runId == "90843e0c-6113-4462-af33-a89ff9731031"
-      st.state == "failed"
+      st.state == BuildState.failed
       st.details == "some very good reason"

src/test/test-project

@@ -1 +1 @@
-Subproject commit df39e07da4799886e6f47cf18f0a5b11e6e9cce2
+Subproject commit 127be8f66fcc6d4d223acf56668d42ff9c37bfb0