Add new option for detailed logging on dependency resolving

This adds command-line arg and config option, with option enabled
aptly is more verbose on internal depeendency resolving cycles:

```
Missing dependencies: file-rc (>= 0.8.16) [amd64], python:any (>= 2.7.1-0ubuntu2) [amd64], python3:any (>= 3.3.2-2~) [amd64], file-rc [amd64], perl (<< 5.17) [amd64], iptables-router (>= 1.2.3) [amd64], systemd [amd64], sgml-base (>= 1.26+nmu2) [amd64], sed (>= 4.1.2-8) [amd64]
Unsatisfied dependency: file-rc (>= 0.8.16) [amd64]
Unsatisfied dependency: python:any (>= 2.7.1-0ubuntu2) [amd64]
Unsatisfied dependency: python3:any (>= 3.3.2-2~) [amd64]
Unsatisfied dependency: file-rc [amd64]
Unsatisfied dependency: perl (<< 5.17) [amd64]
Unsatisfied dependency: iptables-router (>= 1.2.3) [amd64]
Unsatisfied dependency: systemd [amd64]
Injecting package: sgml-base_1.26+nmu4ubuntu1_all
Injecting package: sed_4.2.2-4ubuntu1_amd64
```

cmd/cmd.go

@@ -113,6 +113,7 @@ package environment to new version.`,
 	cmd.Flag.Bool("dep-follow-source", false, "when processing dependencies, follow from binary to Source packages")
 	cmd.Flag.Bool("dep-follow-recommends", false, "when processing dependencies, follow Recommends")
 	cmd.Flag.Bool("dep-follow-all-variants", false, "when processing dependencies, follow a & b if dependency is 'a|b'")
+	cmd.Flag.Bool("dep-verbose-resolve", false, "when processing dependencies, print detailed logs")
 	cmd.Flag.String("architectures", "", "list of architectures to consider during (comma-separated), default to all available")
 	cmd.Flag.String("config", "", "location of configuration file (default locations are /etc/aptly.conf, ~/.aptly.conf)")
 

cmd/mirror_update.go

@@ -69,7 +69,7 @@ func aptlyMirrorUpdate(cmd *commander.Command, args []string) error {
 		}
 
 		var oldLen, newLen int
-		oldLen, newLen, err = repo.ApplyFilter(context.DependencyOptions(), filterQuery)
+		oldLen, newLen, err = repo.ApplyFilter(context.DependencyOptions(), filterQuery, context.Progress())
 		if err != nil {
 			return fmt.Errorf("unable to update: %s", err)
 		}

cmd/repo_move.go

@@ -115,7 +115,7 @@ func aptlyRepoMoveCopyImport(cmd *commander.Command, args []string) error {
 		}
 	}
 
-	toProcess, err := srcList.Filter(queries, withDeps, dstList, context.DependencyOptions(), architecturesList)
+	toProcess, err := srcList.FilterWithProgress(queries, withDeps, dstList, context.DependencyOptions(), architecturesList, context.Progress())
 	if err != nil {
 		return fmt.Errorf("unable to %s: %s", command, err)
 	}

cmd/snapshot_filter.go

@@ -66,7 +66,7 @@ func aptlySnapshotFilter(cmd *commander.Command, args []string) error {
 	}
 
 	// Filter with dependencies as requested
-	result, err := packageList.Filter(queries, withDeps, nil, context.DependencyOptions(), architecturesList)
+	result, err := packageList.FilterWithProgress(queries, withDeps, nil, context.DependencyOptions(), architecturesList, context.Progress())
 	if err != nil {
 		return fmt.Errorf("unable to filter: %s", err)
 	}

cmd/snapshot_pull.go

@@ -96,7 +96,7 @@ func aptlySnapshotPull(cmd *commander.Command, args []string) error {
 	}
 
 	// Filter with dependencies as requested
-	result, err := sourcePackageList.Filter(queries, !noDeps, packageList, context.DependencyOptions(), architecturesList)
+	result, err := sourcePackageList.FilterWithProgress(queries, !noDeps, packageList, context.DependencyOptions(), architecturesList, context.Progress())
 	if err != nil {
 		return fmt.Errorf("unable to pull: %s", err)
 	}

cmd/snapshot_search.go

@@ -99,8 +99,8 @@ func aptlySnapshotMirrorRepoSearch(cmd *commander.Command, args []string) error
 		}
 	}
 
-	result, err := list.Filter([]deb.PackageQuery{q}, withDeps,
+	result, err := list.FilterWithProgress([]deb.PackageQuery{q}, withDeps,
-		nil, context.DependencyOptions(), architecturesList)
+		nil, context.DependencyOptions(), architecturesList, context.Progress())
 	if err != nil {
 		return fmt.Errorf("unable to search: %s", err)
 	}

context/context.go

@@ -149,6 +149,9 @@ func (context *AptlyContext) DependencyOptions() int {
 		if context.lookupOption(context.config().DepFollowSource, "dep-follow-source") {
 			context.dependencyOptions |= deb.DepFollowSource
 		}
+		if context.lookupOption(context.config().DepVerboseResolve, "dep-verbose-resolve") {
+			context.dependencyOptions |= deb.DepVerboseResolve
+		}
 	}
 
 	return context.dependencyOptions

deb/list.go

@@ -3,6 +3,7 @@ package deb
 import (
 	"fmt"
 	"sort"
+	"strings"
 
 	"github.com/smira/aptly/aptly"
 	"github.com/smira/aptly/utils"
@@ -20,6 +21,8 @@ const (
 	DepFollowAllVariants
 	// DepFollowBuild pulls build dependencies
 	DepFollowBuild
+	// DepVerboseResolve emits additional logs while dependencies are being resolved
+	DepVerboseResolve
 )
 
 // PackageList is list of unique (by key) packages
@@ -346,6 +349,14 @@ func (l *PackageList) VerifyDependencies(options int, architectures []string, so
 		progress.ShutdownBar()
 	}
 
+	if options&DepVerboseResolve == DepVerboseResolve && progress != nil {
+		missingStr := make([]string, len(missing))
+		for i := range missing {
+			missingStr[i] = missing[i].String()
+		}
+		progress.ColoredPrintf("@{y}Missing dependencies:@| %s", strings.Join(missingStr, ", "))
+	}
+
 	return missing, nil
 }
 
@@ -462,6 +473,11 @@ func (l *PackageList) Search(dep Dependency, allMatches bool) (searchResults []*
 
 // Filter filters package index by specified queries (ORed together), possibly pulling dependencies
 func (l *PackageList) Filter(queries []PackageQuery, withDependencies bool, source *PackageList, dependencyOptions int, architecturesList []string) (*PackageList, error) {
+	return l.FilterWithProgress(queries, withDependencies, source, dependencyOptions, architecturesList, nil)
+}
+
+// FilterWithProgress filters package index by specified queries (ORed together), possibly pulling dependencies and displays progress
+func (l *PackageList) FilterWithProgress(queries []PackageQuery, withDependencies bool, source *PackageList, dependencyOptions int, architecturesList []string, progress aptly.Progress) (*PackageList, error) {
 	if !l.indexed {
 		panic("list not indexed, can't filter")
 	}
@@ -488,7 +504,7 @@ func (l *PackageList) Filter(queries []PackageQuery, withDependencies bool, sour
 			added = 0
 
 			// find missing dependencies
-			missing, err := result.VerifyDependencies(dependencyOptions, architecturesList, dependencySource, nil)
+			missing, err := result.VerifyDependencies(dependencyOptions, architecturesList, dependencySource, progress)
 			if err != nil {
 				return nil, err
 			}
@@ -501,9 +517,12 @@ func (l *PackageList) Filter(queries []PackageQuery, withDependencies bool, sour
 					continue
 				}
 
-				searchResults := l.Search(dep, false)
+				searchResults := l.Search(dep, true)
 				if searchResults != nil {
 					for _, p := range searchResults {
+						if dependencyOptions&DepVerboseResolve == DepVerboseResolve && progress != nil {
+							progress.ColoredPrintf("@{g}Injecting package@|: %s", p)
+						}
 						result.Add(p)
 						dependencySource.Add(p)
 						added++
@@ -511,6 +530,11 @@ func (l *PackageList) Filter(queries []PackageQuery, withDependencies bool, sour
 							break
 						}
 					}
+				} else {
+					if dependencyOptions&DepVerboseResolve == DepVerboseResolve && progress != nil {
+						progress.ColoredPrintf("@{r}Unsatisfied dependency@|: %s", dep.String())
+					}
+
 				}
 			}
 		}

deb/remote.go

@@ -491,14 +491,14 @@ func (repo *RemoteRepo) DownloadPackageIndexes(progress aptly.Progress, d aptly.
 }
 
 // ApplyFilter applies filtering to already built PackageList
-func (repo *RemoteRepo) ApplyFilter(dependencyOptions int, filterQuery PackageQuery) (oldLen, newLen int, err error) {
+func (repo *RemoteRepo) ApplyFilter(dependencyOptions int, filterQuery PackageQuery, progress aptly.Progress) (oldLen, newLen int, err error) {
 	repo.packageList.PrepareIndex()
 
 	emptyList := NewPackageList()
 	emptyList.PrepareIndex()
 
 	oldLen = repo.packageList.Len()
-	repo.packageList, err = repo.packageList.Filter([]PackageQuery{filterQuery}, repo.FilterWithDeps, emptyList, dependencyOptions, repo.Architectures)
+	repo.packageList, err = repo.packageList.FilterWithProgress([]PackageQuery{filterQuery}, repo.FilterWithDeps, emptyList, dependencyOptions, repo.Architectures, progress)
 	if repo.packageList != nil {
 		newLen = repo.packageList.Len()
 	}

man/aptly.1

@@ -43,6 +43,7 @@ Configuration file is stored in JSON format (default values shown below):
   "dependencyFollowRecommends": false,
   "dependencyFollowAllVariants": false,
   "dependencyFollowSource": false,
+  "dependencyVerboseResolve": false,
   "gpgDisableSign": false,
   "gpgDisableVerify": false,
   "downloadSourcePackages": false,
@@ -119,6 +120,10 @@ when dependency looks like \fBpackage\-a | package\-b\fR, follow both variants a
 follow dependency from binary package to source package
 .
 .TP
+\fBdependencyVerboseResolve\fR
+print additional details while resolving dependencies (useful for debugging)
+.
+.TP
 \fBgpgDisableSign\fR
 don\(cqt sign published repositories with gpg(1), also can be disabled on per\-repo basis using \fB\-skip\-signing\fR flag when publishing
 .
@@ -361,6 +366,10 @@ when processing dependencies, follow from binary to Source packages
 \-\fBdep\-follow\-suggests\fR=false
 when processing dependencies, follow Suggests
 .
+.TP
+\-\fBdep\-verbose\-resolve\fR=false
+when processing dependencies, print detailed logs
+.
 .SH "CREATE NEW MIRROR"
 \fBaptly\fR \fBmirror\fR \fBcreate\fR \fIname\fR \fIarchive url\fR \fIdistribution\fR [\fIcomponent1\fR \|\.\|\.\|\.]
 .

man/aptly.1.ronn.tmpl

@@ -35,6 +35,7 @@ Configuration file is stored in JSON format (default values shown below):
       "dependencyFollowRecommends": false,
       "dependencyFollowAllVariants": false,
       "dependencyFollowSource": false,
+      "dependencyVerboseResolve": false,
       "gpgDisableSign": false,
       "gpgDisableVerify": false,
       "downloadSourcePackages": false,
@@ -99,6 +100,9 @@ Options:
   * `dependencyFollowSource`:
     follow dependency from binary package to source package
 
+  * `dependencyVerboseResolve`:
+    print additional details while resolving dependencies (useful for debugging)
+
   * `gpgDisableSign`:
     don't sign published repositories with gpg(1), also can be disabled on
     per-repo basis using `-skip-signing` flag when publishing

system/t02_config/ConfigShowTest_gold

@@ -7,6 +7,7 @@
     "dependencyFollowRecommends": false,
     "dependencyFollowAllVariants": false,
     "dependencyFollowSource": false,
+    "dependencyVerboseResolve": false,
     "gpgDisableSign": false,
     "gpgDisableVerify": false,
     "downloadSourcePackages": false,

system/t02_config/CreateConfigTest_gold

@@ -7,6 +7,7 @@
   "dependencyFollowRecommends": false,
   "dependencyFollowAllVariants": false,
   "dependencyFollowSource": false,
+  "dependencyVerboseResolve": false,
   "gpgDisableSign": false,
   "gpgDisableVerify": false,
   "downloadSourcePackages": false,

system/t03_help/MainHelpTest_gold

@@ -17,4 +17,5 @@ Options:
   -dep-follow-recommends=false: when processing dependencies, follow Recommends
   -dep-follow-source=false: when processing dependencies, follow from binary to Source packages
   -dep-follow-suggests=false: when processing dependencies, follow Suggests
+  -dep-verbose-resolve=false: when processing dependencies, print detailed logs
 

system/t03_help/MainTest_gold

@@ -25,4 +25,5 @@ Options:
   -dep-follow-recommends=false: when processing dependencies, follow Recommends
   -dep-follow-source=false: when processing dependencies, follow from binary to Source packages
   -dep-follow-suggests=false: when processing dependencies, follow Suggests
+  -dep-verbose-resolve=false: when processing dependencies, print detailed logs
 ERROR: unable to parse command

system/t03_help/MirrorCreateHelpTest_gold

@@ -19,6 +19,7 @@ Options:
   -dep-follow-recommends=false: when processing dependencies, follow Recommends
   -dep-follow-source=false: when processing dependencies, follow from binary to Source packages
   -dep-follow-suggests=false: when processing dependencies, follow Suggests
+  -dep-verbose-resolve=false: when processing dependencies, print detailed logs
   -filter="": filter packages in mirror
   -filter-with-deps=false: when filtering, include dependencies of matching packages as well
   -force-architectures=false: (only with architecture list) skip check that requested architectures are listed in Release file

system/t03_help/MirrorCreateTest_gold

@@ -10,6 +10,7 @@ Options:
   -dep-follow-recommends=false: when processing dependencies, follow Recommends
   -dep-follow-source=false: when processing dependencies, follow from binary to Source packages
   -dep-follow-suggests=false: when processing dependencies, follow Suggests
+  -dep-verbose-resolve=false: when processing dependencies, print detailed logs
   -filter="": filter packages in mirror
   -filter-with-deps=false: when filtering, include dependencies of matching packages as well
   -force-architectures=false: (only with architecture list) skip check that requested architectures are listed in Release file

system/t03_help/MirrorHelpTest_gold

@@ -21,3 +21,4 @@ Options:
   -dep-follow-recommends=false: when processing dependencies, follow Recommends
   -dep-follow-source=false: when processing dependencies, follow from binary to Source packages
   -dep-follow-suggests=false: when processing dependencies, follow Suggests
+  -dep-verbose-resolve=false: when processing dependencies, print detailed logs

system/t03_help/MirrorTest_gold

@@ -21,4 +21,5 @@ Options:
   -dep-follow-recommends=false: when processing dependencies, follow Recommends
   -dep-follow-source=false: when processing dependencies, follow from binary to Source packages
   -dep-follow-suggests=false: when processing dependencies, follow Suggests
+  -dep-verbose-resolve=false: when processing dependencies, print detailed logs
 ERROR: unable to parse command

system/t03_help/WrongFlagTest_gold

@@ -11,6 +11,7 @@ Options:
   -dep-follow-recommends=false: when processing dependencies, follow Recommends
   -dep-follow-source=false: when processing dependencies, follow from binary to Source packages
   -dep-follow-suggests=false: when processing dependencies, follow Suggests
+  -dep-verbose-resolve=false: when processing dependencies, print detailed logs
   -filter="": filter packages in mirror
   -filter-with-deps=false: when filtering, include dependencies of matching packages as well
   -force-architectures=false: (only with architecture list) skip check that requested architectures are listed in Release file

system/t05_snapshot/PullSnapshot15Test_gold

@@ -0,0 +1,33 @@
+
+
+    [snap1]: Snapshot from mirror [wheezy-main]: http://mirror.yandex.ru/debian/ wheezy
+    [snap2]: Snapshot from mirror [wheezy-backports]: http://mirror.yandex.ru/debian/ wheezy-backports
+Building indexes...
+Dependencies would be pulled into snapshot:
+Injecting package: init-system-helpers_1.18~bpo70+1_all
+Injecting package: libestr0_0.1.9-1~bpo70+1_amd64
+Injecting package: libestr0_0.1.9-1~bpo70+1_i386
+Injecting package: libjson-c2_0.11-3~bpo7+1_amd64
+Injecting package: libjson-c2_0.11-3~bpo7+1_i386
+Injecting package: liblogging-stdlog0_1.0.4-1~bpo70+1_amd64
+Injecting package: liblogging-stdlog0_1.0.4-1~bpo70+1_i386
+Loading packages (60863)...
+Missing dependencies: 
+Missing dependencies: libestr0 (>= 0.1.4) [amd64], libjson-c2 (>= 0.10) [amd64], liblogging-stdlog0 (>= 1.0.1) [amd64], init-system-helpers (>= 1.18~) [amd64], libestr0 (>= 0.1.4) [i386], libjson-c2 (>= 0.10) [i386], liblogging-stdlog0 (>= 1.0.1) [i386], init-system-helpers (>= 1.18~) [i386]
+Snapshot snap3 successfully created.
+You can run 'aptly publish snapshot snap3' to publish snapshot as Debian repository.
+[+] init-system-helpers_1.18~bpo70+1_all added
+[+] libestr0_0.1.9-1~bpo70+1_amd64 added
+[+] libestr0_0.1.9-1~bpo70+1_i386 added
+[+] libjson-c2_0.11-3~bpo7+1_amd64 added
+[+] libjson-c2_0.11-3~bpo7+1_i386 added
+[+] liblogging-stdlog0_1.0.4-1~bpo70+1_amd64 added
+[+] liblogging-stdlog0_1.0.4-1~bpo70+1_i386 added
+[+] rsyslog_7.6.3-2~bpo70+1_amd64 added
+[+] rsyslog_7.6.3-2~bpo70+1_i386 added
+[-] libestr0_0.1.1-2_amd64 removed
+[-] libestr0_0.1.1-2_i386 removed
+[-] rsyslog_5.8.11-3_amd64 removed
+[-] rsyslog_5.8.11-3_i386 removed
+and result would be saved as new snapshot snap3.
+from snapshot:

system/t05_snapshot/pull.py

@@ -231,3 +231,16 @@ class PullSnapshot14Test(BaseTest):
         "aptly snapshot create sensu from mirror sensu",
     ]
     runCmd = "aptly snapshot pull -architectures=amd64,i386 -all-matches empty sensu destination 'sensu (>0.12)' 'sensu (<0.9.6)'"
+
+
+class PullSnapshot15Test(BaseTest):
+    """
+    pull snapshot: verbose logs
+    """
+    fixtureDB = True
+    fixtureCmds = [
+        "aptly snapshot create snap1 from mirror wheezy-main",
+        "aptly snapshot create snap2 from mirror wheezy-backports",
+    ]
+    runCmd = "aptly snapshot pull -dep-verbose-resolve snap1 snap2 snap3 'rsyslog (>= 7.4.4)'"
+    outputMatchPrepare = lambda _, output: "\n".join(sorted(output.split("\n")))

utils/config.go

@@ -16,6 +16,7 @@ type ConfigStructure struct {
 	DepFollowRecommends    bool                        `json:"dependencyFollowRecommends"`
 	DepFollowAllVariants   bool                        `json:"dependencyFollowAllVariants"`
 	DepFollowSource        bool                        `json:"dependencyFollowSource"`
+	DepVerboseResolve      bool                        `json:"dependencyVerboseResolve"`
 	GpgDisableSign         bool                        `json:"gpgDisableSign"`
 	GpgDisableVerify       bool                        `json:"gpgDisableVerify"`
 	DownloadSourcePackages bool                        `json:"downloadSourcePackages"`

utils/config_test.go

@@ -57,6 +57,7 @@ func (s *ConfigSuite) TestSaveConfig(c *C) {
 		"  \"dependencyFollowRecommends\": false,\n"+
 		"  \"dependencyFollowAllVariants\": false,\n"+
 		"  \"dependencyFollowSource\": false,\n"+
+		"  \"dependencyVerboseResolve\": false,\n"+
 		"  \"gpgDisableSign\": false,\n"+
 		"  \"gpgDisableVerify\": false,\n"+
 		"  \"downloadSourcePackages\": false,\n"+