bump version to 0.6.2

Add MirrorStatus.LastStarted property

.github/workflows/tunasync.yml

@@ -28,6 +28,11 @@ jobs:
         make tunasync
         make tunasynctl
 
+    - name: Keep artifacts
+      uses: actions/upload-artifact@v1
+      with:
+        name: tunasync-bin
+        path: build/
 
   test:
     name: Test
@@ -65,4 +70,4 @@ jobs:
       uses: coverallsapp/github-action@v1.0.1
       with:
           github-token: ${{ secrets.github_token }}
-          path-to-lcov: coverage.lcov
+          path-to-lcov: coverage.lcov

cmd/tunasynctl/tunasynctl.go

@@ -32,7 +32,7 @@ const (
 	userCfgFile   = "$HOME/.config/tunasync/ctl.conf" // user-specific conf
 )
 
-var logger = logging.MustGetLogger("tunasynctl-cmd")
+var logger = logging.MustGetLogger("tunasynctl")
 
 var baseURL string
 var client *http.Client
@@ -41,7 +41,7 @@ func initializeWrapper(handler cli.ActionFunc) cli.ActionFunc {
 	return func(c *cli.Context) error {
 		err := initialize(c)
 		if err != nil {
-			return cli.NewExitError("", 1)
+			return cli.NewExitError(err.Error(), 1)
 		}
 		return handler(c)
 	}
@@ -55,8 +55,9 @@ type config struct {
 
 func loadConfig(cfgFile string, cfg *config) error {
 	if cfgFile != "" {
+		logger.Infof("Loading config: %s", cfgFile)
 		if _, err := toml.DecodeFile(cfgFile, cfg); err != nil {
-			logger.Errorf(err.Error())
+			// logger.Errorf(err.Error())
 			return err
 		}
 	}
@@ -66,7 +67,7 @@ func loadConfig(cfgFile string, cfg *config) error {
 
 func initialize(c *cli.Context) error {
 	// init logger
-	tunasync.InitLogger(c.Bool("verbose"), c.Bool("verbose"), false)
+	tunasync.InitLogger(c.Bool("verbose"), c.Bool("debug"), false)
 
 	cfg := new(config)
 
@@ -76,14 +77,23 @@ func initialize(c *cli.Context) error {
 
 	// find config file and load config
 	if _, err := os.Stat(systemCfgFile); err == nil {
-		loadConfig(systemCfgFile, cfg)
+		err = loadConfig(systemCfgFile, cfg)
+		if err != nil {
+			return err
+		}
 	}
-	fmt.Println(os.ExpandEnv(userCfgFile))
+	logger.Debug("user config file: %s", os.ExpandEnv(userCfgFile))
 	if _, err := os.Stat(os.ExpandEnv(userCfgFile)); err == nil {
-		loadConfig(os.ExpandEnv(userCfgFile), cfg)
+		err = loadConfig(os.ExpandEnv(userCfgFile), cfg)
+		if err != nil {
+			return err
+		}
 	}
 	if c.String("config") != "" {
-		loadConfig(c.String("config"), cfg)
+		err := loadConfig(c.String("config"), cfg)
+		if err != nil {
+			return err
+		}
 	}
 
 	// override config using the command-line arguments
@@ -112,7 +122,7 @@ func initialize(c *cli.Context) error {
 	client, err = tunasync.CreateHTTPClient(cfg.CACert)
 	if err != nil {
 		err = fmt.Errorf("Error initializing HTTP client: %s", err.Error())
-		logger.Error(err.Error())
+		// logger.Error(err.Error())
 		return err
 
 	}
@@ -135,7 +145,7 @@ func listWorkers(c *cli.Context) error {
 				err.Error()),
 			1)
 	}
-	fmt.Print(string(b))
+	fmt.Println(string(b))
 	return nil
 }
 
@@ -167,14 +177,21 @@ func listJobs(c *cli.Context) error {
 				_, err := tunasync.GetJSON(fmt.Sprintf("%s/workers/%s/jobs",
 					baseURL, workerID), &workerJobs, client)
 				if err != nil {
-					logger.Errorf("Filed to correctly get jobs"+
+					logger.Infof("Failed to correctly get jobs"+
 						" for worker %s: %s", workerID, err.Error())
 				}
 				ans <- workerJobs
 			}(workerID)
 		}
 		for range args {
-			jobs = append(jobs, <-ans...)
+			job := <-ans
+			if job == nil {
+				return cli.NewExitError(
+					fmt.Sprintf("Failed to correctly get information "+
+						"of jobs from at least one manager"),
+					1)
+			}
+			jobs = append(jobs, job...)
 		}
 		genericJobs = jobs
 	}
@@ -182,10 +199,10 @@ func listJobs(c *cli.Context) error {
 	b, err := json.MarshalIndent(genericJobs, "", "  ")
 	if err != nil {
 		return cli.NewExitError(
-			fmt.Sprintf("Error printing out informations: %s", err.Error()),
+			fmt.Sprintf("Error printing out information: %s", err.Error()),
 			1)
 	}
-	fmt.Printf(string(b))
+	fmt.Println(string(b))
 	return nil
 }
 
@@ -236,7 +253,7 @@ func updateMirrorSize(c *cli.Context) error {
 		)
 	}
 
-	logger.Infof("Successfully updated mirror size to %s", mirrorSize)
+	fmt.Printf("Successfully updated mirror size to %s\n", mirrorSize)
 	return nil
 }
 
@@ -279,9 +296,9 @@ func removeWorker(c *cli.Context) error {
 	res := map[string]string{}
 	err = json.NewDecoder(resp.Body).Decode(&res)
 	if res["message"] == "deleted" {
-		logger.Info("Successfully removed the worker")
+		fmt.Println("Successfully removed the worker")
 	} else {
-		logger.Info("Failed to remove the worker")
+		return cli.NewExitError("Failed to remove the worker", 1)
 	}
 	return nil
 }
@@ -314,7 +331,7 @@ func flushDisabledJobs(c *cli.Context) error {
 			1)
 	}
 
-	logger.Info("Successfully flushed disabled jobs")
+	fmt.Println("Successfully flushed disabled jobs")
 	return nil
 }
 
@@ -367,7 +384,7 @@ func cmdJob(cmd tunasync.CmdVerb) cli.ActionFunc {
 				" command: HTTP status code is not 200: %s", body),
 				1)
 		}
-		logger.Info("Succesfully send command")
+		fmt.Println("Successfully send the command")
 
 		return nil
 	}
@@ -405,7 +422,7 @@ func cmdWorker(cmd tunasync.CmdVerb) cli.ActionFunc {
 				" command: HTTP status code is not 200: %s", body),
 				1)
 		}
-		logger.Info("Succesfully send command")
+		fmt.Println("Successfully send the command")
 
 		return nil
 	}
@@ -462,6 +479,10 @@ func main() {
 			Name:  "verbose, v",
 			Usage: "Enable verbosely logging",
 		},
+		cli.BoolFlag{
+			Name:  "debug",
+			Usage: "Enable debugging logging",
+		},
 	}
 	cmdFlags := []cli.Flag{
 		cli.StringFlag{

go.mod

@@ -9,6 +9,7 @@ require (
 	github.com/codeskyblue/go-sh v0.0.0-20190412065543-76bd3d59ff27
 	github.com/dennwc/btrfs v0.0.0-20190517175702-d917b30ff035
 	github.com/gin-gonic/gin v1.5.0
+	github.com/imdario/mergo v0.3.9
 	github.com/mattn/goveralls v0.0.5 // indirect
 	github.com/pkg/profile v1.4.0
 	github.com/ryszard/goskiplist v0.0.0-20150312221310-2dfbae5fcf46

go.sum

@@ -29,6 +29,9 @@ github.com/golang/protobuf v1.3.2 h1:6nsPYzhq5kReh6QImI3k5qWzO4PEbvbIW2cwSfR/6xs
 github.com/golang/protobuf v1.3.2/go.mod h1:6lQm79b+lXiMfvg/cZm0SGofjICqVBUtrP5yJMmIC1U=
 github.com/google/gofuzz v1.0.0/go.mod h1:dBl0BpW6vV/+mYPU4Po3pmUjxk6FQPldtuIdl/M65Eg=
 github.com/gopherjs/gopherjs v0.0.0-20181017120253-0766667cb4d1/go.mod h1:wJfORRmW1u3UXTncJ5qlYoELFm8eSnnEO6hX4iZ3EWY=
+github.com/imdario/mergo v0.3.9 h1:UauaLniWCFHWd+Jp9oCEkTBj8VO/9DKg3PV3VCNMDIg=
+github.com/imdario/mergo v0.3.9/go.mod h1:2EnlNZ0deacrJVfApfmtdGgDfMuh/nq6Ok1EcJh5FfA=
+github.com/json-iterator/go v1.1.7 h1:KfgG9LzI+pYjr4xvmz/5H4FXjokeP+rlHLhv3iH62Fo=
 github.com/json-iterator/go v1.1.7/go.mod h1:KdQUCv79m/52Kvf8AW2vK1V8akMuk1QjK/uOdHXbAo4=
 github.com/jtolds/gls v4.20.0+incompatible h1:xdiiI2gbIgH/gLH7ADydsJ1uDOEzR8yvV7C0MuV77Wo=
 github.com/jtolds/gls v4.20.0+incompatible/go.mod h1:QJZ7F/aHp+rZTRtaJ1ow/lLfFfVYBRgL+9YlvaHOwJU=
@@ -38,7 +41,9 @@ github.com/mattn/go-isatty v0.0.9 h1:d5US/mDsogSGW37IV293h//ZFaeajb69h+EHFsv2xGg
 github.com/mattn/go-isatty v0.0.9/go.mod h1:YNRxwqDuOph6SZLI9vUUz6OYw3QyUt7WiY2yME+cCiQ=
 github.com/mattn/goveralls v0.0.5 h1:spfq8AyZ0cCk57Za6/juJ5btQxeE1FaEGMdfcI+XO48=
 github.com/mattn/goveralls v0.0.5/go.mod h1:Xg2LHi51faXLyKXwsndxiW6uxEEQT9+3sjGzzwU4xy0=
+github.com/modern-go/concurrent v0.0.0-20180228061459-e0a39a4cb421 h1:ZqeYNhU3OHLH3mGKHDcjJRFFRrJa6eAM5H+CtDdOsPc=
 github.com/modern-go/concurrent v0.0.0-20180228061459-e0a39a4cb421/go.mod h1:6dJC0mAP4ikYIbvyc7fijjWJddQyLn8Ig3JB5CqoB9Q=
+github.com/modern-go/reflect2 v0.0.0-20180701023420-4b7aa43c6742 h1:Esafd1046DLDQ0W1YjYsBW+p8U2u7vzgW2SQVmlNazg=
 github.com/modern-go/reflect2 v0.0.0-20180701023420-4b7aa43c6742/go.mod h1:bx2lNnkwVCuqBIxFjflWJWanXIb3RllmbCylyMrvgv0=
 github.com/pkg/profile v1.4.0 h1:uCmaf4vVbWAOZz36k1hrQD7ijGRzLwaME8Am/7a4jZI=
 github.com/pkg/profile v1.4.0/go.mod h1:NWz/XGvpEW1FyYQ7fCx4dqYBLlfTcE+A9FLAkNKqjFE=

internal/logger.go

@@ -24,9 +24,12 @@ func InitLogger(verbose, debug, withSystemd bool) {
 
 	if debug {
 		logging.SetLevel(logging.DEBUG, "tunasync")
+		logging.SetLevel(logging.DEBUG, "tunasynctl")
 	} else if verbose {
 		logging.SetLevel(logging.INFO, "tunasync")
+		logging.SetLevel(logging.INFO, "tunasynctl")
 	} else {
 		logging.SetLevel(logging.NOTICE, "tunasync")
+		logging.SetLevel(logging.NOTICE, "tunasynctl")
 	}
 }

internal/msg.go

@@ -8,16 +8,17 @@ import (
 // A MirrorStatus represents a msg when
 // a worker has done syncing
 type MirrorStatus struct {
-	Name       string     `json:"name"`
-	Worker     string     `json:"worker"`
-	IsMaster   bool       `json:"is_master"`
-	Status     SyncStatus `json:"status"`
-	LastUpdate time.Time  `json:"last_update"`
-	LastEnded  time.Time  `json:"last_ended"`
-	Scheduled  time.Time  `json:"next_schedule"`
-	Upstream   string     `json:"upstream"`
-	Size       string     `json:"size"`
-	ErrorMsg   string     `json:"error_msg"`
+	Name        string     `json:"name"`
+	Worker      string     `json:"worker"`
+	IsMaster    bool       `json:"is_master"`
+	Status      SyncStatus `json:"status"`
+	LastUpdate  time.Time  `json:"last_update"`
+	LastStarted time.Time  `json:"last_started"`
+	LastEnded   time.Time  `json:"last_ended"`
+	Scheduled   time.Time  `json:"next_schedule"`
+	Upstream    string     `json:"upstream"`
+	Size        string     `json:"size"`
+	ErrorMsg    string     `json:"error_msg"`
 }
 
 // A WorkerStatus is the information struct that describe

internal/status_web.go

@@ -38,31 +38,35 @@ func (t *stampTime) UnmarshalJSON(b []byte) error {
 
 // WebMirrorStatus is the mirror status to be shown in the web page
 type WebMirrorStatus struct {
-	Name         string     `json:"name"`
-	IsMaster     bool       `json:"is_master"`
-	Status       SyncStatus `json:"status"`
-	LastUpdate   textTime   `json:"last_update"`
-	LastUpdateTs stampTime  `json:"last_update_ts"`
-	LastEnded    textTime   `json:"last_ended"`
-	LastEndedTs  stampTime  `json:"last_ended_ts"`
-	Scheduled    textTime   `json:"next_schedule"`
-	ScheduledTs  stampTime  `json:"next_schedule_ts"`
-	Upstream     string     `json:"upstream"`
-	Size         string     `json:"size"` // approximate size
+	Name          string     `json:"name"`
+	IsMaster      bool       `json:"is_master"`
+	Status        SyncStatus `json:"status"`
+	LastUpdate    textTime   `json:"last_update"`
+	LastUpdateTs  stampTime  `json:"last_update_ts"`
+	LastStarted   textTime   `json:"last_started"`
+	LastStartedTs stampTime  `json:"last_started_ts"`
+	LastEnded     textTime   `json:"last_ended"`
+	LastEndedTs   stampTime  `json:"last_ended_ts"`
+	Scheduled     textTime   `json:"next_schedule"`
+	ScheduledTs   stampTime  `json:"next_schedule_ts"`
+	Upstream      string     `json:"upstream"`
+	Size          string     `json:"size"` // approximate size
 }
 
 func BuildWebMirrorStatus(m MirrorStatus) WebMirrorStatus {
 	return WebMirrorStatus{
-		Name:         m.Name,
-		IsMaster:     m.IsMaster,
-		Status:       m.Status,
-		LastUpdate:   textTime{m.LastUpdate},
-		LastUpdateTs: stampTime{m.LastUpdate},
-		LastEnded:    textTime{m.LastEnded},
-		LastEndedTs:  stampTime{m.LastEnded},
-		Scheduled:    textTime{m.Scheduled},
-		ScheduledTs:  stampTime{m.Scheduled},
-		Upstream:     m.Upstream,
-		Size:         m.Size,
+		Name:          m.Name,
+		IsMaster:      m.IsMaster,
+		Status:        m.Status,
+		LastUpdate:    textTime{m.LastUpdate},
+		LastUpdateTs:  stampTime{m.LastUpdate},
+		LastStarted:   textTime{m.LastStarted},
+		LastStartedTs: stampTime{m.LastStarted},
+		LastEnded:     textTime{m.LastEnded},
+		LastEndedTs:   stampTime{m.LastEnded},
+		Scheduled:     textTime{m.Scheduled},
+		ScheduledTs:   stampTime{m.Scheduled},
+		Upstream:      m.Upstream,
+		Size:          m.Size,
 	}
 }

internal/status_web_test.go

@@ -15,16 +15,18 @@ func TestStatus(t *testing.T) {
 		So(err, ShouldBeNil)
 		t := time.Date(2016, time.April, 16, 23, 8, 10, 0, loc)
 		m := WebMirrorStatus{
-			Name:         "tunalinux",
-			Status:       Success,
-			LastUpdate:   textTime{t},
-			LastUpdateTs: stampTime{t},
-			LastEnded:    textTime{t},
-			LastEndedTs:  stampTime{t},
-			Scheduled:    textTime{t},
-			ScheduledTs:  stampTime{t},
-			Size:         "5GB",
-			Upstream:     "rsync://mirrors.tuna.tsinghua.edu.cn/tunalinux/",
+			Name:          "tunalinux",
+			Status:        Success,
+			LastUpdate:    textTime{t},
+			LastUpdateTs:  stampTime{t},
+			LastStarted:   textTime{t},
+			LastStartedTs: stampTime{t},
+			LastEnded:     textTime{t},
+			LastEndedTs:   stampTime{t},
+			Scheduled:     textTime{t},
+			ScheduledTs:   stampTime{t},
+			Size:          "5GB",
+			Upstream:      "rsync://mirrors.tuna.tsinghua.edu.cn/tunalinux/",
 		}
 
 		b, err := json.Marshal(m)
@@ -40,6 +42,10 @@ func TestStatus(t *testing.T) {
 		So(m2.LastUpdateTs.Unix(), ShouldEqual, m.LastUpdate.Unix())
 		So(m2.LastUpdate.UnixNano(), ShouldEqual, m.LastUpdate.UnixNano())
 		So(m2.LastUpdateTs.UnixNano(), ShouldEqual, m.LastUpdate.UnixNano())
+		So(m2.LastStarted.Unix(), ShouldEqual, m.LastStarted.Unix())
+		So(m2.LastStartedTs.Unix(), ShouldEqual, m.LastStarted.Unix())
+		So(m2.LastStarted.UnixNano(), ShouldEqual, m.LastStarted.UnixNano())
+		So(m2.LastStartedTs.UnixNano(), ShouldEqual, m.LastStarted.UnixNano())
 		So(m2.LastEnded.Unix(), ShouldEqual, m.LastEnded.Unix())
 		So(m2.LastEndedTs.Unix(), ShouldEqual, m.LastEnded.Unix())
 		So(m2.LastEnded.UnixNano(), ShouldEqual, m.LastEnded.UnixNano())
@@ -53,15 +59,16 @@ func TestStatus(t *testing.T) {
 	})
 	Convey("BuildWebMirrorStatus should work", t, func() {
 		m := MirrorStatus{
-			Name:       "arch-sync3",
-			Worker:     "testWorker",
-			IsMaster:   true,
-			Status:     Failed,
-			LastUpdate: time.Now().Add(-time.Minute * 30),
-			LastEnded:  time.Now(),
-			Scheduled:  time.Now().Add(time.Minute * 5),
-			Upstream:   "mirrors.tuna.tsinghua.edu.cn",
-			Size:       "4GB",
+			Name:        "arch-sync3",
+			Worker:      "testWorker",
+			IsMaster:    true,
+			Status:      Failed,
+			LastUpdate:  time.Now().Add(-time.Minute * 30),
+			LastStarted: time.Now().Add(-time.Minute * 1),
+			LastEnded:   time.Now(),
+			Scheduled:   time.Now().Add(time.Minute * 5),
+			Upstream:    "mirrors.tuna.tsinghua.edu.cn",
+			Size:        "4GB",
 		}
 
 		var m2 WebMirrorStatus
@@ -73,6 +80,10 @@ func TestStatus(t *testing.T) {
 		So(m2.LastUpdateTs.Unix(), ShouldEqual, m.LastUpdate.Unix())
 		So(m2.LastUpdate.UnixNano(), ShouldEqual, m.LastUpdate.UnixNano())
 		So(m2.LastUpdateTs.UnixNano(), ShouldEqual, m.LastUpdate.UnixNano())
+		So(m2.LastStarted.Unix(), ShouldEqual, m.LastStarted.Unix())
+		So(m2.LastStartedTs.Unix(), ShouldEqual, m.LastStarted.Unix())
+		So(m2.LastStarted.UnixNano(), ShouldEqual, m.LastStarted.UnixNano())
+		So(m2.LastStartedTs.UnixNano(), ShouldEqual, m.LastStarted.UnixNano())
 		So(m2.LastEnded.Unix(), ShouldEqual, m.LastEnded.Unix())
 		So(m2.LastEndedTs.Unix(), ShouldEqual, m.LastEnded.Unix())
 		So(m2.LastEnded.UnixNano(), ShouldEqual, m.LastEnded.UnixNano())

internal/util.go

@@ -6,12 +6,37 @@ import (
 	"crypto/x509"
 	"encoding/json"
 	"errors"
+	"fmt"
 	"io/ioutil"
 	"net/http"
+	"os/exec"
 	"regexp"
 	"time"
 )
 
+var rsyncExitValues = map[int]string{
+	0:  "Success",
+	1:  "Syntax or usage error",
+	2:  "Protocol incompatibility",
+	3:  "Errors selecting input/output files, dirs",
+	4:  "Requested action not supported: an attempt was made to manipulate 64-bit files on a platform that cannot support them; or an option was specified that is supported by the client and not by the server.",
+	5:  "Error starting client-server protocol",
+	6:  "Daemon unable to append to log-file",
+	10: "Error in socket I/O",
+	11: "Error in file I/O",
+	12: "Error in rsync protocol data stream",
+	13: "Errors with program diagnostics",
+	14: "Error in IPC code",
+	20: "Received SIGUSR1 or SIGINT",
+	21: "Some error returned by waitpid()",
+	22: "Error allocating core memory buffers",
+	23: "Partial transfer due to error",
+	24: "Partial transfer due to vanished source files",
+	25: "The --max-delete limit stopped deletions",
+	30: "Timeout in data send/receive",
+	35: "Timeout waiting for daemon connection",
+}
+
 // GetTLSConfig generate tls.Config from CAFile
 func GetTLSConfig(CAFile string) (*tls.Config, error) {
 	caCert, err := ioutil.ReadFile(CAFile)
@@ -86,13 +111,45 @@ func GetJSON(url string, obj interface{}, client *http.Client) (*http.Response,
 	return resp, json.Unmarshal(body, obj)
 }
 
-func ExtractSizeFromRsyncLog(content []byte) string {
-	// (?m) flag enables multi-line mode
-	re := regexp.MustCompile(`(?m)^Total file size: ([0-9\.]+[KMGTP]?) bytes`)
-	matches := re.FindAllSubmatch(content, -1)
-	// fmt.Printf("%q\n", matches)
-	if len(matches) == 0 {
+// FindAllSubmatchInFile calls re.FindAllSubmatch to find matches in given file
+func FindAllSubmatchInFile(fileName string, re *regexp.Regexp) (matches [][][]byte, err error) {
+	if fileName == "/dev/null" {
+		err = errors.New("Invalid log file")
+		return
+	}
+	if content, err := ioutil.ReadFile(fileName); err == nil {
+		matches = re.FindAllSubmatch(content, -1)
+		// fmt.Printf("FindAllSubmatchInFile: %q\n", matches)
+	}
+	return
+}
+
+// ExtractSizeFromLog uses a regexp to extract the size from log files
+func ExtractSizeFromLog(logFile string, re *regexp.Regexp) string {
+	matches, _ := FindAllSubmatchInFile(logFile, re)
+	if matches == nil || len(matches) == 0 {
 		return ""
 	}
+	// return the first capture group of the last occurrence
 	return string(matches[len(matches)-1][1])
 }
+
+// ExtractSizeFromRsyncLog extracts the size from rsync logs
+func ExtractSizeFromRsyncLog(logFile string) string {
+	// (?m) flag enables multi-line mode
+	re := regexp.MustCompile(`(?m)^Total file size: ([0-9\.]+[KMGTP]?) bytes`)
+	return ExtractSizeFromLog(logFile, re)
+}
+
+// TranslateRsyncErrorCode translates the exit code of rsync to a message
+func TranslateRsyncErrorCode(cmdErr error) (exitCode int, msg string) {
+
+	if exiterr, ok := cmdErr.(*exec.ExitError); ok {
+		exitCode = exiterr.ExitCode()
+		strerr, valid := rsyncExitValues[exitCode]
+		if valid {
+			msg = fmt.Sprintf("rsync error: %s", strerr)
+		}
+	}
+	return
+}

internal/util_test.go

@@ -1,6 +1,9 @@
 package internal
 
 import (
+	"io/ioutil"
+	"os"
+	"path/filepath"
 	"testing"
 
 	. "github.com/smartystreets/goconvey/convey"
@@ -26,7 +29,14 @@ sent 7.55M bytes  received 823.25M bytes  5.11M bytes/sec
 total size is 1.33T  speedup is 1,604.11
 `
 	Convey("Log parser should work", t, func() {
-		res := ExtractSizeFromRsyncLog([]byte(realLogContent))
+		tmpDir, err := ioutil.TempDir("", "tunasync")
+		So(err, ShouldBeNil)
+		defer os.RemoveAll(tmpDir)
+		logFile := filepath.Join(tmpDir, "rs.log")
+		err = ioutil.WriteFile(logFile, []byte(realLogContent), 0755)
+		So(err, ShouldBeNil)
+
+		res := ExtractSizeFromRsyncLog(logFile)
 		So(res, ShouldEqual, "1.33T")
 	})
 }

internal/version.go

@@ -1,3 +1,4 @@
 package internal
 
-const Version string = "0.4.2"
+// Version of the program
+const Version string = "0.6.2"

manager/db_test.go

@@ -78,34 +78,37 @@ func TestBoltAdapter(t *testing.T) {
 		Convey("update mirror status", func() {
 			status := []MirrorStatus{
 				MirrorStatus{
-					Name:       "arch-sync1",
-					Worker:     testWorkerIDs[0],
-					IsMaster:   true,
-					Status:     Success,
-					LastUpdate: time.Now(),
-					LastEnded:  time.Now(),
-					Upstream:   "mirrors.tuna.tsinghua.edu.cn",
-					Size:       "3GB",
+					Name:        "arch-sync1",
+					Worker:      testWorkerIDs[0],
+					IsMaster:    true,
+					Status:      Success,
+					LastUpdate:  time.Now(),
+					LastStarted: time.Now().Add(-time.Minute),
+					LastEnded:   time.Now(),
+					Upstream:    "mirrors.tuna.tsinghua.edu.cn",
+					Size:        "3GB",
 				},
 				MirrorStatus{
-					Name:       "arch-sync2",
-					Worker:     testWorkerIDs[1],
-					IsMaster:   true,
-					Status:     Disabled,
-					LastUpdate: time.Now().Add(-time.Hour),
-					LastEnded:  time.Now(),
-					Upstream:   "mirrors.tuna.tsinghua.edu.cn",
-					Size:       "4GB",
+					Name:        "arch-sync2",
+					Worker:      testWorkerIDs[1],
+					IsMaster:    true,
+					Status:      Disabled,
+					LastUpdate:  time.Now().Add(-time.Hour),
+					LastStarted: time.Now().Add(-time.Minute),
+					LastEnded:   time.Now(),
+					Upstream:    "mirrors.tuna.tsinghua.edu.cn",
+					Size:        "4GB",
 				},
 				MirrorStatus{
-					Name:       "arch-sync3",
-					Worker:     testWorkerIDs[1],
-					IsMaster:   true,
-					Status:     Success,
-					LastUpdate: time.Now().Add(-time.Second),
-					LastEnded:  time.Now(),
-					Upstream:   "mirrors.tuna.tsinghua.edu.cn",
-					Size:       "4GB",
+					Name:        "arch-sync3",
+					Worker:      testWorkerIDs[1],
+					IsMaster:    true,
+					Status:      Success,
+					LastUpdate:  time.Now().Add(-time.Minute),
+					LastStarted: time.Now().Add(-time.Second),
+					LastEnded:   time.Now(),
+					Upstream:    "mirrors.tuna.tsinghua.edu.cn",
+					Size:        "4GB",
 				},
 			}
 

manager/server.go

@@ -297,14 +297,21 @@ func (s *Manager) updateJobOfWorker(c *gin.Context) {
 
 	curStatus, _ := s.adapter.GetMirrorStatus(workerID, mirrorName)
 
+	curTime := time.Now()
+
+	if status.Status == PreSyncing && curStatus.Status != PreSyncing {
+		status.LastStarted = curTime
+	} else {
+		status.LastStarted = curStatus.LastStarted
+	}
 	// Only successful syncing needs last_update
 	if status.Status == Success {
-		status.LastUpdate = time.Now()
+		status.LastUpdate = curTime
 	} else {
 		status.LastUpdate = curStatus.LastUpdate
 	}
 	if status.Status == Success || status.Status == Failed {
-		status.LastEnded = time.Now()
+		status.LastEnded = curTime
 	} else {
 		status.LastEnded = curStatus.LastEnded
 	}

manager/server_test.go

@@ -151,10 +151,41 @@ func TestHTTPServer(t *testing.T) {
 					So(m.Size, ShouldEqual, status.Size)
 					So(m.IsMaster, ShouldEqual, status.IsMaster)
 					So(time.Now().Sub(m.LastUpdate), ShouldBeLessThan, 1*time.Second)
+					So(m.LastStarted.IsZero(), ShouldBeTrue) // hasn't been initialized yet
 					So(time.Now().Sub(m.LastEnded), ShouldBeLessThan, 1*time.Second)
 
 				})
 
+				// start syncing
+				status.Status = PreSyncing
+				time.Sleep(1 * time.Second)
+				resp, err = PostJSON(fmt.Sprintf("%s/workers/%s/jobs/%s", baseURL, status.Worker, status.Name), status, nil)
+				So(err, ShouldBeNil)
+				defer resp.Body.Close()
+				So(resp.StatusCode, ShouldEqual, http.StatusOK)
+
+				Convey("update mirror status to PreSync - starting sync", func(ctx C) {
+					var ms []MirrorStatus
+					resp, err := GetJSON(baseURL+"/workers/test_worker1/jobs", &ms, nil)
+
+					So(err, ShouldBeNil)
+					So(resp.StatusCode, ShouldEqual, http.StatusOK)
+					// err = json.NewDecoder(resp.Body).Decode(&mirrorStatusList)
+					m := ms[0]
+					So(m.Name, ShouldEqual, status.Name)
+					So(m.Worker, ShouldEqual, status.Worker)
+					So(m.Status, ShouldEqual, status.Status)
+					So(m.Upstream, ShouldEqual, status.Upstream)
+					So(m.Size, ShouldEqual, status.Size)
+					So(m.IsMaster, ShouldEqual, status.IsMaster)
+					So(time.Now().Sub(m.LastUpdate), ShouldBeLessThan, 3*time.Second)
+					So(time.Now().Sub(m.LastUpdate), ShouldBeGreaterThan, 1*time.Second)
+					So(time.Now().Sub(m.LastStarted), ShouldBeLessThan, 2*time.Second)
+					So(time.Now().Sub(m.LastEnded), ShouldBeLessThan, 3*time.Second)
+					So(time.Now().Sub(m.LastEnded), ShouldBeGreaterThan, 1*time.Second)
+
+				})
+
 				Convey("list all job status of all workers", func(ctx C) {
 					var ms []WebMirrorStatus
 					resp, err := GetJSON(baseURL+"/jobs", &ms, nil)
@@ -167,8 +198,9 @@ func TestHTTPServer(t *testing.T) {
 					So(m.Upstream, ShouldEqual, status.Upstream)
 					So(m.Size, ShouldEqual, status.Size)
 					So(m.IsMaster, ShouldEqual, status.IsMaster)
-					So(time.Now().Sub(m.LastUpdate.Time), ShouldBeLessThan, 1*time.Second)
-					So(time.Now().Sub(m.LastEnded.Time), ShouldBeLessThan, 1*time.Second)
+					So(time.Now().Sub(m.LastUpdate.Time), ShouldBeLessThan, 3*time.Second)
+					So(time.Now().Sub(m.LastStarted.Time), ShouldBeLessThan, 2*time.Second)
+					So(time.Now().Sub(m.LastEnded.Time), ShouldBeLessThan, 3*time.Second)
 
 				})
 
@@ -197,8 +229,9 @@ func TestHTTPServer(t *testing.T) {
 						So(m.Upstream, ShouldEqual, status.Upstream)
 						So(m.Size, ShouldEqual, "5GB")
 						So(m.IsMaster, ShouldEqual, status.IsMaster)
-						So(time.Now().Sub(m.LastUpdate), ShouldBeLessThan, 1*time.Second)
-						So(time.Now().Sub(m.LastEnded), ShouldBeLessThan, 1*time.Second)
+						So(time.Now().Sub(m.LastUpdate), ShouldBeLessThan, 3*time.Second)
+						So(time.Now().Sub(m.LastStarted), ShouldBeLessThan, 2*time.Second)
+						So(time.Now().Sub(m.LastEnded), ShouldBeLessThan, 3*time.Second)
 					})
 				})
 
@@ -251,6 +284,7 @@ func TestHTTPServer(t *testing.T) {
 					So(m.Size, ShouldEqual, status.Size)
 					So(m.IsMaster, ShouldEqual, status.IsMaster)
 					So(time.Now().Sub(m.LastUpdate), ShouldBeGreaterThan, 3*time.Second)
+					So(time.Now().Sub(m.LastStarted), ShouldBeGreaterThan, 3*time.Second)
 					So(time.Now().Sub(m.LastEnded), ShouldBeLessThan, 1*time.Second)
 				})
 			})
@@ -258,14 +292,15 @@ func TestHTTPServer(t *testing.T) {
 			Convey("update mirror status of an inexisted worker", func(ctx C) {
 				invalidWorker := "test_worker2"
 				status := MirrorStatus{
-					Name:       "arch-sync2",
-					Worker:     invalidWorker,
-					IsMaster:   true,
-					Status:     Success,
-					LastUpdate: time.Now(),
-					LastEnded:  time.Now(),
-					Upstream:   "mirrors.tuna.tsinghua.edu.cn",
-					Size:       "4GB",
+					Name:        "arch-sync2",
+					Worker:      invalidWorker,
+					IsMaster:    true,
+					Status:      Success,
+					LastUpdate:  time.Now(),
+					LastStarted: time.Now(),
+					LastEnded:   time.Now(),
+					Upstream:    "mirrors.tuna.tsinghua.edu.cn",
+					Size:        "4GB",
 				}
 				resp, err := PostJSON(fmt.Sprintf("%s/workers/%s/jobs/%s",
 					baseURL, status.Worker, status.Name), status, nil)

worker/base_provider.go

@@ -19,6 +19,7 @@ type baseProvider struct {
 	isMaster bool
 
 	cmd       *cmdJob
+	logFileFd *os.File
 	isRunning atomic.Value
 
 	cgroup *cgroupHook
@@ -128,10 +129,19 @@ func (p *baseProvider) prepareLogFile(append bool) error {
 		logger.Errorf("Error opening logfile %s: %s", p.LogFile(), err.Error())
 		return err
 	}
+	p.logFileFd = logFile
 	p.cmd.SetLogFile(logFile)
 	return nil
 }
 
+func (p *baseProvider) closeLogFile() (err error) {
+	if p.logFileFd != nil {
+		err = p.logFileFd.Close()
+		p.logFileFd = nil
+	}
+	return
+}
+
 func (p *baseProvider) Run() error {
 	panic("Not Implemented")
 }

worker/cmd_provider.go

@@ -3,11 +3,11 @@ package worker
 import (
 	"errors"
 	"fmt"
-	"io/ioutil"
 	"regexp"
 	"time"
 
 	"github.com/anmitsu/go-shlex"
+	"github.com/tuna/tunasync/internal"
 )
 
 type cmdConfig struct {
@@ -18,13 +18,16 @@ type cmdConfig struct {
 	retry                       int
 	env                         map[string]string
 	failOnMatch                 string
+	sizePattern                 string
 }
 
 type cmdProvider struct {
 	baseProvider
 	cmdConfig
 	command     []string
+	dataSize    string
 	failOnMatch *regexp.Regexp
+	sizePattern *regexp.Regexp
 }
 
 func newCmdProvider(c cmdConfig) (*cmdProvider, error) {
@@ -59,6 +62,14 @@ func newCmdProvider(c cmdConfig) (*cmdProvider, error) {
 		}
 		provider.failOnMatch = failOnMatch
 	}
+	if len(c.sizePattern) > 0 {
+		var err error
+		sizePattern, err := regexp.Compile(c.sizePattern)
+		if err != nil {
+			return nil, errors.New("size-pattern regexp error: " + err.Error())
+		}
+		provider.sizePattern = sizePattern
+	}
 
 	return provider, nil
 }
@@ -71,7 +82,13 @@ func (p *cmdProvider) Upstream() string {
 	return p.upstreamURL
 }
 
+func (p *cmdProvider) DataSize() string {
+	return p.dataSize
+}
+
 func (p *cmdProvider) Run() error {
+	p.dataSize = ""
+	defer p.closeLogFile()
 	if err := p.Start(); err != nil {
 		return err
 	}
@@ -79,16 +96,18 @@ func (p *cmdProvider) Run() error {
 		return err
 	}
 	if p.failOnMatch != nil {
-		if logContent, err := ioutil.ReadFile(p.LogFile()); err == nil {
-			matches := p.failOnMatch.FindAllSubmatch(logContent, -1)
-			if len(matches) != 0 {
-				logger.Debug("Fail-on-match: %r", matches)
-				return errors.New(
-					fmt.Sprintf("Fail-on-match regexp found %d matches", len(matches)))
-			}
-		} else {
+		matches, err := internal.FindAllSubmatchInFile(p.LogFile(), p.failOnMatch)
+		logger.Infof("FindAllSubmatchInFile: %q\n", matches)
+		if err != nil {
 			return err
 		}
+		if len(matches) != 0 {
+			logger.Debug("Fail-on-match: %r", matches)
+			return fmt.Errorf("Fail-on-match regexp found %d matches", len(matches))
+		}
+	}
+	if p.sizePattern != nil {
+		p.dataSize = internal.ExtractSizeFromLog(p.LogFile(), p.sizePattern)
 	}
 	return nil
 }

worker/config.go

@@ -6,6 +6,7 @@ import (
 	"path/filepath"
 
 	"github.com/BurntSushi/toml"
+	"github.com/imdario/mergo"
 )
 
 type providerEnum uint8
@@ -41,7 +42,8 @@ type Config struct {
 	BtrfsSnapshot btrfsSnapshotConfig `toml:"btrfs_snapshot"`
 	Docker        dockerConfig        `toml:"docker"`
 	Include       includeConfig       `toml:"include"`
-	Mirrors       []mirrorConfig      `toml:"mirrors"`
+	MirrorsConf   []mirrorConfig      `toml:"mirrors"`
+	Mirrors       []mirrorConfig
 }
 
 type globalConfig struct {
@@ -111,15 +113,16 @@ type includedMirrorConfig struct {
 }
 
 type mirrorConfig struct {
-	Name      string            `toml:"name"`
-	Provider  providerEnum      `toml:"provider"`
-	Upstream  string            `toml:"upstream"`
-	Interval  int               `toml:"interval"`
-	Retry     int               `toml:"retry"`
-	MirrorDir string            `toml:"mirror_dir"`
-	LogDir    string            `toml:"log_dir"`
-	Env       map[string]string `toml:"env"`
-	Role      string            `toml:"role"`
+	Name         string            `toml:"name"`
+	Provider     providerEnum      `toml:"provider"`
+	Upstream     string            `toml:"upstream"`
+	Interval     int               `toml:"interval"`
+	Retry        int               `toml:"retry"`
+	MirrorDir    string            `toml:"mirror_dir"`
+	MirrorSubDir string            `toml:"mirror_subdir"`
+	LogDir       string            `toml:"log_dir"`
+	Env          map[string]string `toml:"env"`
+	Role         string            `toml:"role"`
 
 	// These two options over-write the global options
 	ExecOnSuccess []string `toml:"exec_on_success"`
@@ -131,6 +134,7 @@ type mirrorConfig struct {
 
 	Command       string   `toml:"command"`
 	FailOnMatch   string   `toml:"fail_on_match"`
+	SizePattern   string   `toml:"size_pattern"`
 	UseIPv6       bool     `toml:"use_ipv6"`
 	UseIPv4       bool     `toml:"use_ipv4"`
 	ExcludeFile   string   `toml:"exclude_file"`
@@ -147,6 +151,8 @@ type mirrorConfig struct {
 	DockerOptions []string `toml:"docker_options"`
 
 	SnapshotPath string `toml:"snapshot_path"`
+
+	ChildMirrors []mirrorConfig `toml:"mirrors"`
 }
 
 // LoadConfig loads configuration
@@ -173,9 +179,36 @@ func LoadConfig(cfgFile string) (*Config, error) {
 				logger.Errorf(err.Error())
 				return nil, err
 			}
-			cfg.Mirrors = append(cfg.Mirrors, incMirCfg.Mirrors...)
+			cfg.MirrorsConf = append(cfg.MirrorsConf, incMirCfg.Mirrors...)
+		}
+	}
+
+	for _, m := range cfg.MirrorsConf {
+		if err := recursiveMirrors(cfg, nil, m); err != nil {
+			return nil, err
 		}
 	}
 
 	return cfg, nil
 }
+
+func recursiveMirrors(cfg *Config, parent *mirrorConfig, mirror mirrorConfig) error {
+	var curMir mirrorConfig
+	if parent != nil {
+		curMir = *parent
+	}
+	curMir.ChildMirrors = nil
+	if err := mergo.Merge(&curMir, mirror, mergo.WithOverride); err != nil {
+		return err
+	}
+	if mirror.ChildMirrors == nil {
+		cfg.Mirrors = append(cfg.Mirrors, curMir)
+	} else {
+		for _, m := range mirror.ChildMirrors {
+			if err := recursiveMirrors(cfg, &curMir, m); err != nil {
+				return err
+			}
+		}
+	}
+	return nil
+}

worker/config_test.go

@@ -83,9 +83,9 @@ exec_on_failure = [
 			tmpDir,
 		)
 
-		cfgBlob = cfgBlob + incSection
+		curCfgBlob := cfgBlob + incSection
 
-		err = ioutil.WriteFile(tmpfile.Name(), []byte(cfgBlob), 0644)
+		err = ioutil.WriteFile(tmpfile.Name(), []byte(curCfgBlob), 0644)
 		So(err, ShouldEqual, nil)
 		defer tmpfile.Close()
 
@@ -157,6 +157,102 @@ use_ipv6 = true
 		So(len(cfg.Mirrors), ShouldEqual, 6)
 	})
 
+	Convey("Everything should work on nested config file", t, func() {
+		tmpfile, err := ioutil.TempFile("", "tunasync")
+		So(err, ShouldEqual, nil)
+		defer os.Remove(tmpfile.Name())
+
+		tmpDir, err := ioutil.TempDir("", "tunasync")
+		So(err, ShouldBeNil)
+		defer os.RemoveAll(tmpDir)
+
+		incSection := fmt.Sprintf(
+			"\n[include]\n"+
+				"include_mirrors = \"%s/*.conf\"",
+			tmpDir,
+		)
+
+		curCfgBlob := cfgBlob + incSection
+
+		err = ioutil.WriteFile(tmpfile.Name(), []byte(curCfgBlob), 0644)
+		So(err, ShouldEqual, nil)
+		defer tmpfile.Close()
+
+		incBlob1 := `
+[[mirrors]]
+name = "ipv6s"
+use_ipv6 = true
+	[[mirrors.mirrors]]
+	name = "debians"
+	mirror_subdir = "debian"
+	provider = "two-stage-rsync"
+	stage1_profile = "debian"
+
+		[[mirrors.mirrors.mirrors]]
+		name = "debian-security"
+		upstream = "rsync://test.host/debian-security/"
+		[[mirrors.mirrors.mirrors]]
+		name = "ubuntu"
+		stage1_profile = "ubuntu"
+		upstream = "rsync://test.host2/ubuntu/"
+	[[mirrors.mirrors]]
+	name = "debian-cd"
+	provider = "rsync"
+	upstream = "rsync://test.host3/debian-cd/"
+		`
+		err = ioutil.WriteFile(filepath.Join(tmpDir, "nest.conf"), []byte(incBlob1), 0644)
+		So(err, ShouldEqual, nil)
+
+		cfg, err := LoadConfig(tmpfile.Name())
+		So(err, ShouldBeNil)
+		So(cfg.Global.Name, ShouldEqual, "test_worker")
+		So(cfg.Global.Interval, ShouldEqual, 240)
+		So(cfg.Global.Retry, ShouldEqual, 3)
+		So(cfg.Global.MirrorDir, ShouldEqual, "/data/mirrors")
+
+		So(cfg.Manager.APIBase, ShouldEqual, "https://127.0.0.1:5000")
+		So(cfg.Server.Hostname, ShouldEqual, "worker1.example.com")
+
+		m := cfg.Mirrors[0]
+		So(m.Name, ShouldEqual, "AOSP")
+		So(m.MirrorDir, ShouldEqual, "/data/git/AOSP")
+		So(m.Provider, ShouldEqual, provCommand)
+		So(m.Interval, ShouldEqual, 720)
+		So(m.Retry, ShouldEqual, 2)
+		So(m.Env["REPO"], ShouldEqual, "/usr/local/bin/aosp-repo")
+
+		m = cfg.Mirrors[1]
+		So(m.Name, ShouldEqual, "debian")
+		So(m.MirrorDir, ShouldEqual, "")
+		So(m.Provider, ShouldEqual, provTwoStageRsync)
+
+		m = cfg.Mirrors[2]
+		So(m.Name, ShouldEqual, "fedora")
+		So(m.MirrorDir, ShouldEqual, "")
+		So(m.Provider, ShouldEqual, provRsync)
+		So(m.ExcludeFile, ShouldEqual, "/etc/tunasync.d/fedora-exclude.txt")
+
+		m = cfg.Mirrors[3]
+		So(m.Name, ShouldEqual, "debian-security")
+		So(m.MirrorDir, ShouldEqual, "")
+		So(m.Provider, ShouldEqual, provTwoStageRsync)
+		So(m.UseIPv6, ShouldEqual, true)
+		So(m.Stage1Profile, ShouldEqual, "debian")
+
+		m = cfg.Mirrors[4]
+		So(m.Name, ShouldEqual, "ubuntu")
+		So(m.MirrorDir, ShouldEqual, "")
+		So(m.Provider, ShouldEqual, provTwoStageRsync)
+		So(m.UseIPv6, ShouldEqual, true)
+		So(m.Stage1Profile, ShouldEqual, "ubuntu")
+
+		m = cfg.Mirrors[5]
+		So(m.Name, ShouldEqual, "debian-cd")
+		So(m.UseIPv6, ShouldEqual, true)
+		So(m.Provider, ShouldEqual, provRsync)
+
+		So(len(cfg.Mirrors), ShouldEqual, 6)
+	})
 	Convey("Providers can be inited from a valid config file", t, func() {
 		tmpfile, err := ioutil.TempFile("", "tunasync")
 		So(err, ShouldEqual, nil)
@@ -207,4 +303,90 @@ use_ipv6 = true
 		So(rp.excludeFile, ShouldEqual, "/etc/tunasync.d/fedora-exclude.txt")
 
 	})
+
+	Convey("MirrorSubdir should work", t, func() {
+		tmpfile, err := ioutil.TempFile("", "tunasync")
+		So(err, ShouldEqual, nil)
+		defer os.Remove(tmpfile.Name())
+
+		cfgBlob1 := `
+[global]
+name = "test_worker"
+log_dir = "/var/log/tunasync/{{.Name}}"
+mirror_dir = "/data/mirrors"
+concurrent = 10
+interval = 240
+retry = 3
+
+[manager]
+api_base = "https://127.0.0.1:5000"
+token = "some_token"
+
+[server]
+hostname = "worker1.example.com"
+listen_addr = "127.0.0.1"
+listen_port = 6000
+ssl_cert = "/etc/tunasync.d/worker1.cert"
+ssl_key = "/etc/tunasync.d/worker1.key"
+
+[[mirrors]]
+name = "ipv6s"
+use_ipv6 = true
+	[[mirrors.mirrors]]
+	name = "debians"
+	mirror_subdir = "debian"
+	provider = "two-stage-rsync"
+	stage1_profile = "debian"
+
+		[[mirrors.mirrors.mirrors]]
+		name = "debian-security"
+		upstream = "rsync://test.host/debian-security/"
+		[[mirrors.mirrors.mirrors]]
+		name = "ubuntu"
+		stage1_profile = "ubuntu"
+		upstream = "rsync://test.host2/ubuntu/"
+	[[mirrors.mirrors]]
+	name = "debian-cd"
+	provider = "rsync"
+	upstream = "rsync://test.host3/debian-cd/"
+		`
+		err = ioutil.WriteFile(tmpfile.Name(), []byte(cfgBlob1), 0644)
+		So(err, ShouldEqual, nil)
+		defer tmpfile.Close()
+
+		cfg, err := LoadConfig(tmpfile.Name())
+		So(err, ShouldBeNil)
+
+		providers := map[string]mirrorProvider{}
+		for _, m := range cfg.Mirrors {
+			p := newMirrorProvider(m, cfg)
+			providers[p.Name()] = p
+		}
+
+		p := providers["debian-security"]
+		So(p.Name(), ShouldEqual, "debian-security")
+		So(p.LogDir(), ShouldEqual, "/var/log/tunasync/debian-security")
+		So(p.LogFile(), ShouldEqual, "/var/log/tunasync/debian-security/latest.log")
+		r2p, ok := p.(*twoStageRsyncProvider)
+		So(ok, ShouldBeTrue)
+		So(r2p.stage1Profile, ShouldEqual, "debian")
+		So(r2p.WorkingDir(), ShouldEqual, "/data/mirrors/debian/debian-security")
+
+		p = providers["ubuntu"]
+		So(p.Name(), ShouldEqual, "ubuntu")
+		So(p.LogDir(), ShouldEqual, "/var/log/tunasync/ubuntu")
+		So(p.LogFile(), ShouldEqual, "/var/log/tunasync/ubuntu/latest.log")
+		r2p, ok = p.(*twoStageRsyncProvider)
+		So(ok, ShouldBeTrue)
+		So(r2p.stage1Profile, ShouldEqual, "ubuntu")
+		So(r2p.WorkingDir(), ShouldEqual, "/data/mirrors/debian/ubuntu")
+
+		p = providers["debian-cd"]
+		So(p.Name(), ShouldEqual, "debian-cd")
+		So(p.LogDir(), ShouldEqual, "/var/log/tunasync/debian-cd")
+		So(p.LogFile(), ShouldEqual, "/var/log/tunasync/debian-cd/latest.log")
+		rp, ok := p.(*rsyncProvider)
+		So(ok, ShouldBeTrue)
+		So(rp.WorkingDir(), ShouldEqual, "/data/mirrors/debian-cd")
+	})
 }

worker/provider.go

@@ -82,7 +82,7 @@ func newMirrorProvider(mirror mirrorConfig, cfg *Config) mirrorProvider {
 	}
 	if mirrorDir == "" {
 		mirrorDir = filepath.Join(
-			cfg.Global.MirrorDir, mirror.Name,
+			cfg.Global.MirrorDir, mirror.MirrorSubDir, mirror.Name,
 		)
 	}
 	if mirror.Interval == 0 {
@@ -113,6 +113,7 @@ func newMirrorProvider(mirror mirrorConfig, cfg *Config) mirrorProvider {
 			command:     mirror.Command,
 			workingDir:  mirrorDir,
 			failOnMatch: mirror.FailOnMatch,
+			sizePattern: mirror.SizePattern,
 			logDir:      logDir,
 			logFile:     filepath.Join(logDir, "latest.log"),
 			interval:    time.Duration(mirror.Interval) * time.Minute,
@@ -135,6 +136,7 @@ func newMirrorProvider(mirror mirrorConfig, cfg *Config) mirrorProvider {
 			excludeFile:       mirror.ExcludeFile,
 			extraOptions:      mirror.RsyncOptions,
 			overriddenOptions: mirror.RsyncOverride,
+			rsyncEnv:          mirror.Env,
 			workingDir:        mirrorDir,
 			logDir:            logDir,
 			logFile:           filepath.Join(logDir, "latest.log"),
@@ -159,6 +161,7 @@ func newMirrorProvider(mirror mirrorConfig, cfg *Config) mirrorProvider {
 			password:      mirror.Password,
 			excludeFile:   mirror.ExcludeFile,
 			extraOptions:  mirror.RsyncOptions,
+			rsyncEnv:      mirror.Env,
 			workingDir:    mirrorDir,
 			logDir:        logDir,
 			logFile:       filepath.Join(logDir, "latest.log"),

worker/provider_test.go

@@ -5,6 +5,7 @@ import (
 	"io/ioutil"
 	"os"
 	"path/filepath"
+	"strconv"
 	"testing"
 	"time"
 
@@ -90,7 +91,7 @@ exit 0
 				fmt.Sprintf(
 					"-aHvh --no-o --no-g --stats --exclude .~tmp~/ "+
 						"--delete --delete-after --delay-updates --safe-links "+
-						"--timeout=120 --contimeout=120 -6 %s %s",
+						"--timeout=120 -6 %s %s",
 					provider.upstreamURL, provider.WorkingDir(),
 				),
 			)
@@ -105,6 +106,34 @@ exit 0
 		})
 
 	})
+	Convey("If the rsync program fails", t, func() {
+		tmpDir, err := ioutil.TempDir("", "tunasync")
+		defer os.RemoveAll(tmpDir)
+		So(err, ShouldBeNil)
+		tmpFile := filepath.Join(tmpDir, "log_file")
+
+		Convey("in the rsyncProvider", func() {
+
+			c := rsyncConfig{
+				name:         "tuna",
+				upstreamURL:  "rsync://rsync.tuna.moe/tuna/",
+				workingDir:   tmpDir,
+				logDir:       tmpDir,
+				logFile:      tmpFile,
+				extraOptions: []string{"--somethine-invalid"},
+				interval:     600 * time.Second,
+			}
+
+			provider, err := newRsyncProvider(c)
+			So(err, ShouldBeNil)
+
+			err = provider.Run()
+			So(err, ShouldNotBeNil)
+			loggedContent, err := ioutil.ReadFile(provider.LogFile())
+			So(err, ShouldBeNil)
+			So(string(loggedContent), ShouldContainSubstring, "Syntax or usage error")
+		})
+	})
 }
 
 func TestRsyncProviderWithAuthentication(t *testing.T) {
@@ -114,6 +143,7 @@ func TestRsyncProviderWithAuthentication(t *testing.T) {
 		So(err, ShouldBeNil)
 		scriptFile := filepath.Join(tmpDir, "myrsync")
 		tmpFile := filepath.Join(tmpDir, "log_file")
+		proxyAddr := "127.0.0.1:1233"
 
 		c := rsyncConfig{
 			name:         "tuna",
@@ -123,6 +153,7 @@ func TestRsyncProviderWithAuthentication(t *testing.T) {
 			password:     "tunasyncpassword",
 			workingDir:   tmpDir,
 			extraOptions: []string{"--delete-excluded"},
+			rsyncEnv:     map[string]string{"RSYNC_PROXY": proxyAddr},
 			logDir:       tmpDir,
 			logFile:      tmpFile,
 			useIPv4:      true,
@@ -141,7 +172,7 @@ func TestRsyncProviderWithAuthentication(t *testing.T) {
 		Convey("Let's try a run", func() {
 			scriptContent := `#!/bin/bash
 echo "syncing to $(pwd)"
-echo $USER $RSYNC_PASSWORD $@
+echo $USER $RSYNC_PASSWORD $RSYNC_PROXY $@
 sleep 1
 echo "Done"
 exit 0
@@ -156,10 +187,11 @@ exit 0
 					"Done\n",
 				targetDir,
 				fmt.Sprintf(
-					"%s %s -aHvh --no-o --no-g --stats --exclude .~tmp~/ "+
+					"%s %s %s -aHvh --no-o --no-g --stats --exclude .~tmp~/ "+
 						"--delete --delete-after --delay-updates --safe-links "+
-						"--timeout=120 --contimeout=120 -4 --delete-excluded %s %s",
-					provider.username, provider.password, provider.upstreamURL, provider.WorkingDir(),
+						"--timeout=120 -4 --delete-excluded %s %s",
+					provider.username, provider.password, proxyAddr,
+					provider.upstreamURL, provider.WorkingDir(),
 				),
 			)
 
@@ -312,7 +344,7 @@ echo $AOSP_REPO_BIN
 
 		Convey("If a long job is killed", func(ctx C) {
 			scriptContent := `#!/bin/bash
-sleep 5
+sleep 10
 			`
 			err = ioutil.WriteFile(scriptFile, []byte(scriptContent), 0755)
 			So(err, ShouldBeNil)
@@ -362,7 +394,7 @@ sleep 5
 
 		})
 	})
-	Convey("Command Provider with fail-on-match regexp should work", t, func(ctx C) {
+	Convey("Command Provider with RegExprs should work", t, func(ctx C) {
 		tmpDir, err := ioutil.TempDir("", "tunasync")
 		defer os.RemoveAll(tmpDir)
 		So(err, ShouldBeNil)
@@ -373,28 +405,73 @@ sleep 5
 			upstreamURL: "http://mirrors.tuna.moe/",
 			command:     "uptime",
 			failOnMatch: "",
+			sizePattern: "",
 			workingDir:  tmpDir,
 			logDir:      tmpDir,
 			logFile:     tmpFile,
 			interval:    600 * time.Second,
 		}
 
-		Convey("when regexp matches", func() {
+		Convey("when fail-on-match regexp matches", func() {
 			c.failOnMatch = `[a-z]+`
 			provider, err := newCmdProvider(c)
 			So(err, ShouldBeNil)
 
+			err = provider.Run()
+			So(err, ShouldNotBeNil)
+			So(provider.DataSize(), ShouldBeEmpty)
+		})
+
+		Convey("when fail-on-match regexp does not match", func() {
+			c.failOnMatch = `load average_`
+			provider, err := newCmdProvider(c)
+			So(err, ShouldBeNil)
+
+			err = provider.Run()
+			So(err, ShouldBeNil)
+		})
+
+		Convey("when fail-on-match regexp meets /dev/null", func() {
+			c.failOnMatch = `load average_`
+			c.logFile = "/dev/null"
+			provider, err := newCmdProvider(c)
+			So(err, ShouldBeNil)
+
 			err = provider.Run()
 			So(err, ShouldNotBeNil)
 		})
 
-		Convey("when regexp does not match", func() {
-			c.failOnMatch = `load average_`
+		Convey("when size-pattern regexp matches", func() {
+			c.sizePattern = `load average: ([\d\.]+)`
 			provider, err := newCmdProvider(c)
 			So(err, ShouldBeNil)
 
 			err = provider.Run()
 			So(err, ShouldBeNil)
+			So(provider.DataSize(), ShouldNotBeEmpty)
+			_, err = strconv.ParseFloat(provider.DataSize(), 32)
+			So(err, ShouldBeNil)
+		})
+
+		Convey("when size-pattern regexp does not match", func() {
+			c.sizePattern = `load ave: ([\d\.]+)`
+			provider, err := newCmdProvider(c)
+			So(err, ShouldBeNil)
+
+			err = provider.Run()
+			So(err, ShouldBeNil)
+			So(provider.DataSize(), ShouldBeEmpty)
+		})
+
+		Convey("when size-pattern regexp meets /dev/null", func() {
+			c.sizePattern = `load ave: ([\d\.]+)`
+			c.logFile = "/dev/null"
+			provider, err := newCmdProvider(c)
+			So(err, ShouldBeNil)
+
+			err = provider.Run()
+			So(err, ShouldNotBeNil)
+			So(provider.DataSize(), ShouldBeEmpty)
 		})
 	})
 }
@@ -457,7 +534,7 @@ exit 0
 				targetDir,
 				fmt.Sprintf(
 					"-aHvh --no-o --no-g --stats --exclude .~tmp~/ --safe-links "+
-						"--timeout=120 --contimeout=120 --exclude dists/ -6 "+
+						"--timeout=120 --exclude dists/ -6 "+
 						"--exclude-from %s %s %s",
 					provider.excludeFile, provider.upstreamURL, provider.WorkingDir(),
 				),
@@ -465,7 +542,7 @@ exit 0
 				fmt.Sprintf(
 					"-aHvh --no-o --no-g --stats --exclude .~tmp~/ "+
 						"--delete --delete-after --delay-updates --safe-links "+
-						"--timeout=120 --contimeout=120 --delete-excluded --cache -6 --exclude-from %s %s %s",
+						"--timeout=120 --delete-excluded --cache -6 --exclude-from %s %s %s",
 					provider.excludeFile, provider.upstreamURL, provider.WorkingDir(),
 				),
 			)
@@ -479,7 +556,7 @@ exit 0
 		Convey("Try terminating", func(ctx C) {
 			scriptContent := `#!/bin/bash
 echo $@
-sleep 4
+sleep 10
 exit 0
 			`
 			err = ioutil.WriteFile(scriptFile, []byte(scriptContent), 0755)
@@ -496,15 +573,45 @@ exit 0
 
 			expectedOutput := fmt.Sprintf(
 				"-aHvh --no-o --no-g --stats --exclude .~tmp~/ --safe-links "+
-					"--timeout=120 --contimeout=120 --exclude dists/ -6 "+
+					"--timeout=120 --exclude dists/ -6 "+
 					"--exclude-from %s %s %s\n",
 				provider.excludeFile, provider.upstreamURL, provider.WorkingDir(),
 			)
 
 			loggedContent, err := ioutil.ReadFile(provider.LogFile())
 			So(err, ShouldBeNil)
-			So(string(loggedContent), ShouldEqual, expectedOutput)
+			So(string(loggedContent), ShouldStartWith, expectedOutput)
 			// fmt.Println(string(loggedContent))
 		})
 	})
+
+	Convey("If the rsync program fails", t, func(ctx C) {
+		tmpDir, err := ioutil.TempDir("", "tunasync")
+		defer os.RemoveAll(tmpDir)
+		So(err, ShouldBeNil)
+		tmpFile := filepath.Join(tmpDir, "log_file")
+
+		Convey("in the twoStageRsyncProvider", func() {
+
+			c := twoStageRsyncConfig{
+				name:          "tuna-two-stage-rsync",
+				upstreamURL:   "rsync://0.0.0.1/",
+				stage1Profile: "debian",
+				workingDir:    tmpDir,
+				logDir:        tmpDir,
+				logFile:       tmpFile,
+				excludeFile:   tmpFile,
+			}
+
+			provider, err := newTwoStageRsyncProvider(c)
+			So(err, ShouldBeNil)
+
+			err = provider.Run()
+			So(err, ShouldNotBeNil)
+			loggedContent, err := ioutil.ReadFile(provider.LogFile())
+			So(err, ShouldBeNil)
+			So(string(loggedContent), ShouldContainSubstring, "Error in socket I/O")
+
+		})
+	})
 }

worker/rsync_provider.go

@@ -2,7 +2,6 @@ package worker
 
 import (
 	"errors"
-	"io/ioutil"
 	"strings"
 	"time"
 
@@ -15,6 +14,7 @@ type rsyncConfig struct {
 	upstreamURL, username, password, excludeFile string
 	extraOptions                                 []string
 	overriddenOptions                            []string
+	rsyncEnv                                     map[string]string
 	workingDir, logDir, logFile                  string
 	useIPv6, useIPv4                             bool
 	interval                                     time.Duration
@@ -50,12 +50,21 @@ func newRsyncProvider(c rsyncConfig) (*rsyncProvider, error) {
 	if c.rsyncCmd == "" {
 		provider.rsyncCmd = "rsync"
 	}
+	if c.rsyncEnv == nil {
+		provider.rsyncEnv = map[string]string{}
+	}
+	if c.username != "" {
+		provider.rsyncEnv["USER"] = c.username
+	}
+	if c.password != "" {
+		provider.rsyncEnv["RSYNC_PASSWORD"] = c.password
+	}
 
 	options := []string{
 		"-aHvh", "--no-o", "--no-g", "--stats",
 		"--exclude", ".~tmp~/",
 		"--delete", "--delete-after", "--delay-updates",
-		"--safe-links", "--timeout=120", "--contimeout=120",
+		"--safe-links", "--timeout=120",
 	}
 	if c.overriddenOptions != nil {
 		options = c.overriddenOptions
@@ -96,15 +105,21 @@ func (p *rsyncProvider) DataSize() string {
 
 func (p *rsyncProvider) Run() error {
 	p.dataSize = ""
+	defer p.closeLogFile()
 	if err := p.Start(); err != nil {
 		return err
 	}
 	if err := p.Wait(); err != nil {
+		code, msg := internal.TranslateRsyncErrorCode(err)
+		if code != 0 {
+			logger.Debug("Rsync exitcode %d (%s)", code, msg)
+			if p.logFileFd != nil {
+				p.logFileFd.WriteString(msg + "\n")
+			}
+		}
 		return err
 	}
-	if logContent, err := ioutil.ReadFile(p.LogFile()); err == nil {
-		p.dataSize = internal.ExtractSizeFromRsyncLog(logContent)
-	}
+	p.dataSize = internal.ExtractSizeFromRsyncLog(p.LogFile())
 	return nil
 }
 
@@ -116,18 +131,11 @@ func (p *rsyncProvider) Start() error {
 		return errors.New("provider is currently running")
 	}
 
-	env := map[string]string{}
-	if p.username != "" {
-		env["USER"] = p.username
-	}
-	if p.password != "" {
-		env["RSYNC_PASSWORD"] = p.password
-	}
 	command := []string{p.rsyncCmd}
 	command = append(command, p.options...)
 	command = append(command, p.upstreamURL, p.WorkingDir())
 
-	p.cmd = newCmdJob(p, command, p.WorkingDir(), env)
+	p.cmd = newCmdJob(p, command, p.WorkingDir(), p.rsyncEnv)
 	if err := p.prepareLogFile(false); err != nil {
 		return err
 	}

worker/runner.go

@@ -118,9 +118,6 @@ func (c *cmdJob) Wait() error {
 		return c.retErr
 	default:
 		err := c.cmd.Wait()
-		if c.cmd.Stdout != nil {
-			c.cmd.Stdout.(*os.File).Close()
-		}
 		c.retErr = err
 		close(c.finished)
 		return err

worker/two_stage_rsync_provider.go

@@ -3,7 +3,6 @@ package worker
 import (
 	"errors"
 	"fmt"
-	"io/ioutil"
 	"strings"
 	"time"
 
@@ -16,6 +15,7 @@ type twoStageRsyncConfig struct {
 	stage1Profile                                string
 	upstreamURL, username, password, excludeFile string
 	extraOptions                                 []string
+	rsyncEnv                                     map[string]string
 	workingDir, logDir, logFile                  string
 	useIPv6                                      bool
 	interval                                     time.Duration
@@ -59,16 +59,25 @@ func newTwoStageRsyncProvider(c twoStageRsyncConfig) (*twoStageRsyncProvider, er
 		stage1Options: []string{
 			"-aHvh", "--no-o", "--no-g", "--stats",
 			"--exclude", ".~tmp~/",
-			"--safe-links", "--timeout=120", "--contimeout=120",
+			"--safe-links", "--timeout=120",
 		},
 		stage2Options: []string{
 			"-aHvh", "--no-o", "--no-g", "--stats",
 			"--exclude", ".~tmp~/",
 			"--delete", "--delete-after", "--delay-updates",
-			"--safe-links", "--timeout=120", "--contimeout=120",
+			"--safe-links", "--timeout=120",
 		},
 	}
 
+	if c.rsyncEnv == nil {
+		provider.rsyncEnv = map[string]string{}
+	}
+	if c.username != "" {
+		provider.rsyncEnv["USER"] = c.username
+	}
+	if c.password != "" {
+		provider.rsyncEnv["RSYNC_PASSWORD"] = c.password
+	}
 	if c.rsyncCmd == "" {
 		provider.rsyncCmd = "rsync"
 	}
@@ -132,14 +141,6 @@ func (p *twoStageRsyncProvider) Run() error {
 		return errors.New("provider is currently running")
 	}
 
-	env := map[string]string{}
-	if p.username != "" {
-		env["USER"] = p.username
-	}
-	if p.password != "" {
-		env["RSYNC_PASSWORD"] = p.password
-	}
-
 	p.dataSize = ""
 	stages := []int{1, 2}
 	for _, stage := range stages {
@@ -151,10 +152,11 @@ func (p *twoStageRsyncProvider) Run() error {
 		command = append(command, options...)
 		command = append(command, p.upstreamURL, p.WorkingDir())
 
-		p.cmd = newCmdJob(p, command, p.WorkingDir(), env)
+		p.cmd = newCmdJob(p, command, p.WorkingDir(), p.rsyncEnv)
 		if err := p.prepareLogFile(stage > 1); err != nil {
 			return err
 		}
+		defer p.closeLogFile()
 
 		if err = p.cmd.Start(); err != nil {
 			return err
@@ -166,11 +168,16 @@ func (p *twoStageRsyncProvider) Run() error {
 		err = p.Wait()
 		p.Lock()
 		if err != nil {
+			code, msg := internal.TranslateRsyncErrorCode(err)
+			if code != 0 {
+				logger.Debug("Rsync exitcode %d (%s)", code, msg)
+				if p.logFileFd != nil {
+					p.logFileFd.WriteString(msg + "\n")
+				}
+			}
 			return err
 		}
 	}
-	if logContent, err := ioutil.ReadFile(p.LogFile()); err == nil {
-		p.dataSize = internal.ExtractSizeFromRsyncLog(logContent)
-	}
+	p.dataSize = internal.ExtractSizeFromRsyncLog(p.LogFile())
 	return nil
 }