tests: show status of the partial test-snapd-huge snap in econnreset test

image/helpers.go

@@ -221,6 +221,8 @@ func (tsto *ToolingStore) DownloadSnap(name string, revision snap.Revision, opts
 		targetDir = pwd
 	}
 
+	logger.Debugf("Going to download snap %q (%s) from channel %q to %q.", name, revision, opts.Channel, opts.TargetDir)
+
 	actions := []*store.SnapAction{{
 		Action:   "download",
 		Name:     name,
@@ -248,6 +250,7 @@ func (tsto *ToolingStore) DownloadSnap(name string, revision snap.Revision, opts
 			logger.Debugf("not downloading, using existing file %s", targetFn)
 			return targetFn, snap, nil
 		}
+		logger.Debugf("File exists but has wrong hash, ignoring (here).")
 	}
 
 	pb := progress.MakeProgressBar()

store/store.go

@@ -1325,6 +1325,7 @@ func (s *Store) Download(ctx context.Context, name string, targetPath string, do
 	}
 
 	if err := s.cacher.Get(downloadInfo.Sha3_384, targetPath); err == nil {
+		logger.Debugf("Cache hit for SHA3_384 …%.5s.", downloadInfo.Sha3_384)
 		return nil
 	}
 
@@ -1358,6 +1359,11 @@ func (s *Store) Download(ctx context.Context, name string, targetPath string, do
 			os.Remove(w.Name())
 		}
 	}()
+	if resume > 0 {
+		logger.Debugf("Resuming download of %q at %d.", partialPath, resume)
+	} else {
+		logger.Debugf("Starting download of %q.", partialPath)
+	}
 
 	authAvail, err := s.authAvailable(user)
 	if err != nil {
@@ -1391,6 +1397,7 @@ func (s *Store) Download(ctx context.Context, name string, targetPath string, do
 	// If hashsum is incorrect retry once
 	if _, ok := err.(HashError); ok {
 		logger.Debugf("Hashsum error on download: %v", err.Error())
+		logger.Debugf("Truncating and trying again from scratch.")
 		err = w.Truncate(0)
 		if err != nil {
 			return err

tests/main/econnreset/task.yaml

@@ -9,18 +9,25 @@ restore: |
 # with the distro
 backends: [-autopkgtest]
 
+debug: |
+    echo "Partial download status"
+    ls -lh test-snapd-huge_* || true
+    echo "other dir content"
+    ls -lh
+
 execute: |
     echo "Downloading a large snap in the background"
     rm -f test-snapd-huge_*
-    su -c "/usr/bin/env SNAPD_DEBUG=1 snap download --edge test-snapd-huge 2>snap-download.log" test &
+    su -c "/usr/bin/env SNAPD_DEBUG=1 SNAPD_DEBUG_HTTP=3 snap download --edge test-snapd-huge 2>snap-download.log" test &
 
     echo "Wait until the download started and downloaded more than 1 MB"
-    for _ in $(seq 40); do
+    echo "starting: $(date)"
+    for _ in $(seq 400); do
         partial=$(find . -name 'test-snapd-huge_*.snap.partial' | head -1)
         if [ -n "$partial" ] && [ "$(stat -c%s "$partial")" -gt "$(( 1024 * 1024 ))" ]; then
             break
         fi
-        sleep 1
+        sleep 0.1
     done
 
     if [ ! -f "$partial" ] || [ "$(stat -c%s "$partial")" -eq 0 ]; then
@@ -29,6 +36,13 @@ execute: |
         exit 1
     fi
 
+    if [ -n "$(find . -name 'test-snapd-huge_*.snap')" ]; then
+        echo "File fully downloaded before the test could act"
+        echo "Test broken"
+        echo "end: $(date)"
+        exit 1
+    fi
+
     echo "Block the download using iptables"
     iptables -I OUTPUT -m owner --uid-owner "$(id -u test)" -j REJECT -p tcp --reject-with tcp-reset
 
@@ -44,3 +58,5 @@ execute: |
     # Note that the download will not be successful because of the nature of
     # the netfilter testbed. When snap download retries the next attempt will
     # end up with a "connection refused" error, something we do not retry
+debug: |
+    cat snap-download.log