This job view page is being replaced by Spyglass soon. Check out the new job view.
PRtylerferrara: Abstract a request counter's cycle logic from watch()
ResultFAILURE
Tests 0 failed / 0 succeeded
Started2021-07-29 22:44
Elapsed41s
Revisionfedb790a848e893f819debd358ff2fb5f6180969
Refs 376

No Test Failures!


Error lines from build-log.txt

... skipping 16 lines ...
time="2021-07-29T22:45:34Z" level=info msg="(cafec0ffee) TRANSACTION VERIFIED: {Action: \"INSERT\", FQIN: \"us.gcr.io/k8s-artifacts-prod/kas-network-proxy/proxy-agent@sha256:c419394f3fa40c32352be5a6ec5865270376d4351a3756bb1893be3f28fcba32\", PQIN: \"us.gcr.io/k8s-artifacts-prod/kas-network-proxy/proxy-agent:v0.0.8\", Path: \"us.gcr.io/k8s-artifacts-prod/kas-network-proxy/proxy-agent\", Digest: \"sha256:c419394f3fa40c32352be5a6ec5865270376d4351a3756bb1893be3f28fcba32\", Tag: \"v0.0.8\"}: agrees with manifest\n"
time="2021-07-29T22:45:34Z" level=info msg="Request {gcr.io/k8s-staging-kas-network-proxy   true}: OK\n"
time="2021-07-29T22:45:34Z" level=info msg="Request {gcr.io/k8s-staging-kas-network-proxy/proxy-agent   false}: OK\n"
time="2021-07-29T22:45:34Z" level=info msg="Request {{gcr.io/k8s-staging-kas-network-proxy   true} proxy-agent v0.0.8 sha256:c419394f3fa40c32352be5a6ec5865270376d4351a3756bb1893be3f28fcba32}: OK\n"
time="2021-07-29T22:45:34Z" level=info msg="(cafec0ffee): looking for child digest sha256:8735603bbd7153b8bfc8d2460481282bb44e2e830e5b237738e5c3e2a58c8f45"
time="2021-07-29T22:45:34Z" level=info msg="(cafec0ffee) TRANSACTION VERIFIED: {Action: \"INSERT\", FQIN: \"us.gcr.io/k8s-artifacts-prod/kas-network-proxy/proxy-agent@sha256:8735603bbd7153b8bfc8d2460481282bb44e2e830e5b237738e5c3e2a58c8f45\", PQIN: \"\", Path: \"us.gcr.io/k8s-artifacts-prod/kas-network-proxy/proxy-agent\", Digest: \"sha256:8735603bbd7153b8bfc8d2460481282bb44e2e830e5b237738e5c3e2a58c8f45\", Tag: \"\"}: agrees with manifest (parent digest sha256:c419394f3fa40c32352be5a6ec5865270376d4351a3756bb1893be3f28fcba32)\n"
time="2021-07-29T22:45:34Z" level=error msg="(cafec0ffee) TRANSACTION REJECTED: could not find matching source registry for us.gcr.io/k8s-artifacts-prod/kas-network-proxy/proxy-agent-white-powder@sha256:c419394f3fa40c32352be5a6ec5865270376d4351a3756bb1893be3f28fcba32"
time="2021-07-29T22:45:34Z" level=info msg="Request {gcr.io/k8s-staging-kas-network-proxy   true}: OK\n"
time="2021-07-29T22:45:34Z" level=info msg="Request {gcr.io/k8s-staging-kas-network-proxy/proxy-agent   false}: OK\n"
time="2021-07-29T22:45:34Z" level=info msg="Request {{gcr.io/k8s-staging-kas-network-proxy   true} proxy-agent v0.0.8 sha256:c419394f3fa40c32352be5a6ec5865270376d4351a3756bb1893be3f28fcba32}: OK\n"
time="2021-07-29T22:45:34Z" level=info msg="(cafec0ffee): looking for child digest sha256:c419394f3fa40c32352be5a6ec5865270376d4351a3756bb1893be3f28fcba32"
time="2021-07-29T22:45:34Z" level=error msg="(cafec0ffee) TRANSACTION REJECTED: {Action: \"INSERT\", FQIN: \"us.gcr.io/k8s-artifacts-prod/kas-network-proxy/proxy-agent@sha256:c419394f3fa40c32352be5a6ec5865270376d4351a3756bb1893be3f28fcba32\", PQIN: \"us.gcr.io/k8s-artifacts-prod/kas-network-proxy/proxy-agent:evil\", Path: \"us.gcr.io/k8s-artifacts-prod/kas-network-proxy/proxy-agent\", Digest: \"sha256:c419394f3fa40c32352be5a6ec5865270376d4351a3756bb1893be3f28fcba32\", Tag: \"evil\"}: could not validate"
time="2021-07-29T22:45:34Z" level=error msg="(cafec0ffee) TRANSACTION REJECTED: validation failure: {Action: \"DELETE\", FQIN: \"us.gcr.io/k8s-artifacts-prod/kas-network-proxy/proxy-agent@sha256:c419394f3fa40c32352be5a6ec5865270376d4351a3756bb1893be3f28fcba32\", PQIN: \"\", Path: \"us.gcr.io/k8s-artifacts-prod/kas-network-proxy/proxy-agent\", Digest: \"sha256:c419394f3fa40c32352be5a6ec5865270376d4351a3756bb1893be3f28fcba32\", Tag: \"\"}: deletions are prohibited"
time="2021-07-29T22:45:34Z" level=error msg="(cafec0ffee) TRANSACTION REJECTED: validation failure: {Action: \"DELETE\", FQIN: \"\", PQIN: \"us.gcr.io/k8s-artifacts-prod/kas-network-proxy/proxy-agent:v0.0.8\", Path: \"us.gcr.io/k8s-artifacts-prod/kas-network-proxy/proxy-agent\", Digest: \"\", Tag: \"v0.0.8\"}: deletions are prohibited"
time="2021-07-29T22:45:34Z" level=error msg="(cafec0ffee) TRANSACTION REJECTED: validation failure: {Action: \"DELETE\", FQIN: \"us.gcr.io/k8s-artifacts-prod/secret@sha256:c419394f3fa40c32352be5a6ec5865270376d4351a3756bb1893be3f28fcba32\", PQIN: \"\", Path: \"us.gcr.io/k8s-artifacts-prod/secret\", Digest: \"sha256:c419394f3fa40c32352be5a6ec5865270376d4351a3756bb1893be3f28fcba32\", Tag: \"\"}: deletions are prohibited"
time="2021-07-29T22:45:34Z" level=error msg="(cafec0ffee) TRANSACTION REJECTED: validation failure: {Action: \"DELETE\", FQIN: \"\", PQIN: \"us.gcr.io/k8s-artifacts-prod/secret:v0.0.8\", Path: \"us.gcr.io/k8s-artifacts-prod/secret\", Digest: \"\", Tag: \"v0.0.8\"}: deletions are prohibited"
time="2021-07-29T22:45:34Z" level=info msg="Request {gcr.io/k8s-staging-etcd   true}: OK\n"
time="2021-07-29T22:45:34Z" level=info msg="Request {gcr.io/k8s-staging-etcd/etcd   false}: OK\n"
time="2021-07-29T22:45:34Z" level=info msg="Request {{gcr.io/k8s-staging-etcd   true} etcd 3.4.7-2 sha256:bcdd5657b1edc1a2eb27356f33dd66b9400d4a084209c33461c7a7da0a32ebb3}: OK\n"
time="2021-07-29T22:45:34Z" level=info msg="(cafec0ffee): looking for child digest sha256:0873d877318546c6569e1abfafd75e0625c202d24435299c4d2e57eeebea52ee"
time="2021-07-29T22:45:34Z" level=info msg="(cafec0ffee) TRANSACTION VERIFIED: {Action: \"INSERT\", FQIN: \"us.gcr.io/k8s-artifacts-prod/kubernetes/etcd@sha256:0873d877318546c6569e1abfafd75e0625c202d24435299c4d2e57eeebea52ee\", PQIN: \"\", Path: \"us.gcr.io/k8s-artifacts-prod/kubernetes/etcd\", Digest: \"sha256:0873d877318546c6569e1abfafd75e0625c202d24435299c4d2e57eeebea52ee\", Tag: \"\"}: agrees with manifest (parent digest sha256:bcdd5657b1edc1a2eb27356f33dd66b9400d4a084209c33461c7a7da0a32ebb3)\n"
time="2021-07-29T22:45:34Z" level=info msg="Request {gcr.io/google-containers   true}: OK\n"
... skipping 12 lines ...
?   	sigs.k8s.io/k8s-container-image-promoter/legacy/container	[no test files]
=== RUN   TestImageRemovalCheck
--- PASS: TestImageRemovalCheck (0.00s)
=== RUN   TestImageSizeCheck
--- PASS: TestImageSizeCheck (0.00s)
=== RUN   TestImageVulnCheck
time="2021-07-29T22:45:34Z" level=error msg="{\n  \"ImageName\": \"foo\",\n  \"Digest\": \"sha256:000\",\n  \"OccurrenceName\": \"\",\n  \"Vulnerability\": {\n    \"severity\": 2,\n    \"fix_available\": true\n  }\n}"
time="2021-07-29T22:45:34Z" level=info msg="Request {{   false} {foo } sha256:000 {   false} {foo }}: OK\n"
time="2021-07-29T22:45:34Z" level=error msg="{\n  \"ImageName\": \"bar\",\n  \"Digest\": \"sha256:111\",\n  \"OccurrenceName\": \"\",\n  \"Vulnerability\": {\n    \"severity\": 3,\n    \"fix_available\": true\n  }\n}"
time="2021-07-29T22:45:34Z" level=info msg="Request {{   false} {bar } sha256:111 {   false} {bar/1 }}: OK\n"
time="2021-07-29T22:45:34Z" level=error msg="Request {{{   false} {bar } sha256:111 {   false} {bar/1 }} <nil>}: error(s) encountered: [{Vulnerability Occurrence w/ Fix Available {\n  \"ImageName\": \"bar\",\n  \"Digest\": \"sha256:111\",\n  \"OccurrenceName\": \"\",\n  \"Vulnerability\": {\n    \"severity\": 4,\n    \"fix_available\": true\n  }\n}}]\n"
time="2021-07-29T22:45:34Z" level=error msg="Request {{{   false} {foo } sha256:000 {   false} {foo }} <nil>}: error(s) encountered: [{Vulnerability Occurrence w/ Fix Available {\n  \"ImageName\": \"foo\",\n  \"Digest\": \"sha256:000\",\n  \"OccurrenceName\": \"\",\n  \"Vulnerability\": {\n    \"severity\": 4,\n    \"fix_available\": true\n  }\n}}]\n"
time="2021-07-29T22:45:34Z" level=error msg="Request {{{   false} {foo } sha256:000 {   false} {foo }} <nil>}: error(s) encountered: [{Vulnerability Occurrence w/ Fix Available {\n  \"ImageName\": \"foo\",\n  \"Digest\": \"sha256:000\",\n  \"OccurrenceName\": \"\",\n  \"Vulnerability\": {\n    \"severity\": 4,\n    \"fix_available\": true\n  }\n}}]\n"
time="2021-07-29T22:45:34Z" level=error msg="Request {{{   false} {bar } sha256:111 {   false} {bar/1 }} <nil>}: error(s) encountered: [{Vulnerability Occurrence w/ Fix Available {\n  \"ImageName\": \"bar\",\n  \"Digest\": \"sha256:111\",\n  \"OccurrenceName\": \"\",\n  \"Vulnerability\": {\n    \"severity\": 5,\n    \"fix_available\": true\n  }\n}} {Vulnerability Occurrence w/ Fix Available {\n  \"ImageName\": \"bar\",\n  \"Digest\": \"sha256:111\",\n  \"OccurrenceName\": \"\",\n  \"Vulnerability\": {\n    \"severity\": 4,\n    \"fix_available\": true\n  }\n}}]\n"
time="2021-07-29T22:45:34Z" level=error msg="Request {{{   false} {bar } sha256:111 {   false} {bar/1 }} <nil>}: error(s) encountered: [{Vulnerability Occurrence w/ Fix Available {\n  \"ImageName\": \"bar\",\n  \"Digest\": \"sha256:111\",\n  \"OccurrenceName\": \"\",\n  \"Vulnerability\": {\n    \"severity\": 4,\n    \"fix_available\": true\n  }\n}}]\n"
time="2021-07-29T22:45:34Z" level=error msg="{\n  \"ImageName\": \"foo\",\n  \"Digest\": \"sha256:000\",\n  \"OccurrenceName\": \"\",\n  \"Vulnerability\": {\n    \"severity\": 4\n  }\n}"
time="2021-07-29T22:45:34Z" level=error msg="{\n  \"ImageName\": \"foo\",\n  \"Digest\": \"sha256:000\",\n  \"OccurrenceName\": \"\",\n  \"Vulnerability\": {\n    \"severity\": 5\n  }\n}"
time="2021-07-29T22:45:34Z" level=info msg="Request {{   false} {foo } sha256:000 {   false} {foo }}: OK\n"
--- PASS: TestImageVulnCheck (0.00s)
=== RUN   TestFindManifest
time="2021-07-29T22:45:34Z" level=info msg="*looking at \"/home/prow/go/src/sigs.k8s.io/k8s-container-image-promoter/legacy/dockerregistry/inventory_test/TestFindManifest/singleton\""
time="2021-07-29T22:45:34Z" level=info msg="1 manifests parsed"
time="2021-07-29T22:45:34Z" level=info msg="*looking at \"/home/prow/go/src/sigs.k8s.io/k8s-container-image-promoter/legacy/dockerregistry/inventory_test/TestFindManifest/singleton\""
... skipping 26 lines ...
time="2021-07-29T22:45:34Z" level=info msg="redundant promotion: multiple edges want to promote the same digest to the same destination endpoint asia.gcr.io/some-prod/foo-controller:1.0:"
time="2021-07-29T22:45:34Z" level=info msg="{{gcr.io/foo-staging sa@robot.com  true} {foo-controller 1.0} sha256:aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa {asia.gcr.io/some-prod sa@robot.com  false} {foo-controller 1.0}}"
time="2021-07-29T22:45:34Z" level=info msg="{{gcr.io/bar-staging sa@robot.com  true} {foo-controller 1.0} sha256:aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa {asia.gcr.io/some-prod sa@robot.com  false} {foo-controller 1.0}}"
time="2021-07-29T22:45:34Z" level=info msg="using the first one: {{gcr.io/foo-staging sa@robot.com  true} {foo-controller 1.0} sha256:aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa {asia.gcr.io/some-prod sa@robot.com  false} {foo-controller 1.0}}"
time="2021-07-29T22:45:34Z" level=info msg="*looking at \"/home/prow/go/src/sigs.k8s.io/k8s-container-image-promoter/legacy/dockerregistry/inventory_test/TestValidateThinManifestsFromDir/valid/malformed-directory-tree-structure-bad-prefix-is-ignored\""
time="2021-07-29T22:45:34Z" level=info msg="*looking at \"/home/prow/go/src/sigs.k8s.io/k8s-container-image-promoter/legacy/dockerregistry/inventory_test/TestValidateThinManifestsFromDir/invalid/overlapping-destination-vertices-different-digest\""
time="2021-07-29T22:45:34Z" level=error msg="multiple edges want to promote *different* images (digests) to the same destination endpoint us.gcr.io/some-prod/foo-controller:1.0:"
time="2021-07-29T22:45:34Z" level=error msg="  for digest sha256:bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb:\n"
time="2021-07-29T22:45:34Z" level=error msg="{{gcr.io/foo-staging sa@robot.com  true} {foo-controller 1.0} sha256:bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb {us.gcr.io/some-prod sa@robot.com  false} {foo-controller 1.0}}\n"
time="2021-07-29T22:45:34Z" level=error msg="  for digest sha256:aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa:\n"
time="2021-07-29T22:45:34Z" level=error msg="{{gcr.io/foo-staging sa@robot.com  true} {foo-controller 1.0} sha256:aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa {us.gcr.io/some-prod sa@robot.com  false} {foo-controller 1.0}}\n"
time="2021-07-29T22:45:34Z" level=error msg="multiple edges want to promote *different* images (digests) to the same destination endpoint eu.gcr.io/some-prod/foo-controller:1.0:"
time="2021-07-29T22:45:34Z" level=error msg="  for digest sha256:bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb:\n"
time="2021-07-29T22:45:34Z" level=error msg="{{gcr.io/foo-staging sa@robot.com  true} {foo-controller 1.0} sha256:bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb {eu.gcr.io/some-prod sa@robot.com  false} {foo-controller 1.0}}\n"
time="2021-07-29T22:45:34Z" level=error msg="  for digest sha256:aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa:\n"
time="2021-07-29T22:45:34Z" level=error msg="{{gcr.io/foo-staging sa@robot.com  true} {foo-controller 1.0} sha256:aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa {eu.gcr.io/some-prod sa@robot.com  false} {foo-controller 1.0}}\n"
time="2021-07-29T22:45:34Z" level=error msg="multiple edges want to promote *different* images (digests) to the same destination endpoint asia.gcr.io/some-prod/foo-controller:1.0:"
time="2021-07-29T22:45:34Z" level=error msg="  for digest sha256:bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb:\n"
time="2021-07-29T22:45:34Z" level=error msg="{{gcr.io/foo-staging sa@robot.com  true} {foo-controller 1.0} sha256:bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb {asia.gcr.io/some-prod sa@robot.com  false} {foo-controller 1.0}}\n"
time="2021-07-29T22:45:34Z" level=error msg="  for digest sha256:aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa:\n"
time="2021-07-29T22:45:34Z" level=error msg="{{gcr.io/foo-staging sa@robot.com  true} {foo-controller 1.0} sha256:aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa {asia.gcr.io/some-prod sa@robot.com  false} {foo-controller 1.0}}\n"
time="2021-07-29T22:45:34Z" level=info msg="*looking at \"/home/prow/go/src/sigs.k8s.io/k8s-container-image-promoter/legacy/dockerregistry/inventory_test/TestValidateThinManifestsFromDir/invalid/malformed-directory-tree-structure\""
time="2021-07-29T22:45:34Z" level=info msg="*looking at \"/home/prow/go/src/sigs.k8s.io/k8s-container-image-promoter/legacy/dockerregistry/inventory_test/TestValidateThinManifestsFromDir/invalid/malformed-directory-tree-structure-nested\""
time="2021-07-29T22:45:34Z" level=warning msg="stat /home/prow/go/src/sigs.k8s.io/k8s-container-image-promoter/legacy/dockerregistry/inventory_test/TestValidateThinManifestsFromDir/invalid/malformed-directory-tree-structure-nested/manifests/b/promoter-manifest.yaml: no such file or directory"
time="2021-07-29T22:45:34Z" level=warning msg="stat /home/prow/go/src/sigs.k8s.io/k8s-container-image-promoter/legacy/dockerregistry/inventory_test/TestValidateThinManifestsFromDir/invalid/malformed-directory-tree-structure-nested/manifests/images/promoter-manifest.yaml: no such file or directory"
--- PASS: TestValidateThinManifestsFromDir (0.00s)
=== RUN   TestParseImageDigest
... skipping 32 lines ...
=== RUN   TestSetManipulationsRegInvImageTag
--- PASS: TestSetManipulationsRegInvImageTag (0.00s)
=== RUN   TestToPromotionEdges
time="2021-07-29T22:45:34Z" level=info msg="edge {{gcr.io/foo robot  true} {a 0.9} sha256:000 {gcr.io/bar robot  false} {a 0.9}}: skipping because it was already promoted (case 1)\n"
time="2021-07-29T22:45:34Z" level=info msg="edge {{gcr.io/foo robot  true} {a 0.9} sha256:000 {gcr.io/bar robot  false} {a 0.9}}: skipping because it was already promoted (case 1)\n"
time="2021-07-29T22:45:34Z" level=info msg="edge {{gcr.io/foo robot  true} {a 0.9} sha256:000 {gcr.io/cat robot  false} {a 0.9}}: skipping because it was already promoted (case 1)\n"
time="2021-07-29T22:45:34Z" level=error msg="edge {{gcr.io/foo robot  true} {c 2.0} sha256:333 {gcr.io/cat robot  false} {c 2.0}}: tag 2.0: ERROR: tag move detected from sha256:333 to sha256:222"
time="2021-07-29T22:45:34Z" level=error msg="edge {{gcr.io/foo robot  true} {c 3.0} sha256:222 {gcr.io/bar robot  false} {c 3.0}}: tag 3.0: ERROR: tag move detected from sha256:222 to sha256:333"
time="2021-07-29T22:45:34Z" level=error msg="edge {{gcr.io/foo robot  true} {c 3.0} sha256:222 {gcr.io/cat robot  false} {c 3.0}}: tag 3.0: ERROR: tag move detected from sha256:222 to sha256:333"
time="2021-07-29T22:45:34Z" level=error msg="edge {{gcr.io/foo robot  true} {c 2.0} sha256:333 {gcr.io/bar robot  false} {c 2.0}}: tag 2.0: ERROR: tag move detected from sha256:333 to sha256:222"
--- PASS: TestToPromotionEdges (0.00s)
=== RUN   TestCheckOverlappingEdges
time="2021-07-29T22:45:34Z" level=error msg="multiple edges want to promote *different* images (digests) to the same destination endpoint gcr.io/bar/a:0.9:"
time="2021-07-29T22:45:34Z" level=error msg="  for digest sha256:000:\n"
time="2021-07-29T22:45:34Z" level=error msg="{{gcr.io/foo robot  true} {a 0.9} sha256:000 {gcr.io/bar robot  false} {a 0.9}}\n"
time="2021-07-29T22:45:34Z" level=error msg="  for digest sha256:111:\n"
time="2021-07-29T22:45:34Z" level=error msg="{{gcr.io/foo robot  true} {b 0.9} sha256:111 {gcr.io/bar robot  false} {a 0.9}}\n"
--- PASS: TestCheckOverlappingEdges (0.00s)
=== RUN   TestRunChecks
time="2021-07-29T22:45:34Z" level=error msg="there was an error in the pull request check"
time="2021-07-29T22:45:34Z" level=error msg="there was an error in the pull request check"
time="2021-07-29T22:45:34Z" level=error msg="there was an error in the pull request check"
--- PASS: TestRunChecks (0.00s)
=== RUN   TestPromotion
time="2021-07-29T22:45:34Z" level=info msg="Nothing to promote."
time="2021-07-29T22:45:34Z" level=info msg="edge {{gcr.io/foo robot  true} {a 0.9} sha256:000 {gcr.io/bar robot  false} {a 0.9}}: skipping because it was already promoted (case 1)\n"
time="2021-07-29T22:45:34Z" level=info msg="edge {{gcr.io/foo robot  true} {a 0.9} sha256:000 {gcr.io/cat robot  false} {a 0.9}}: skipping because it was already promoted (case 1)\n"
time="2021-07-29T22:45:34Z" level=info msg="Nothing to promote."
... skipping 14 lines ...
time="2021-07-29T22:45:34Z" level=info msg="edge {{gcr.io/foo robot  true} {a 0.9} sha256:000 {gcr.io/bar robot  false} {a 0.9}}: regular promotion (neither digest nor pqin exists in dst)\n"
time="2021-07-29T22:45:34Z" level=info msg="edge {{gcr.io/foo robot  true} {a 0.9} sha256:000 {gcr.io/cat robot  false} {a 0.9}}: skipping because it was already promoted (case 1)\n"
time="2021-07-29T22:45:34Z" level=info msg="Pending promotions:"
time="2021-07-29T22:45:34Z" level=info msg="  {{gcr.io/foo robot  true} {a 0.9} sha256:000 {gcr.io/bar robot  false} {a 0.9}}\n"
time="2021-07-29T22:45:34Z" level=info msg="---------- BEGIN PROMOTION ----------"
time="2021-07-29T22:45:34Z" level=info msg="Request <nil>: OK\n"
time="2021-07-29T22:45:34Z" level=error msg="edge {{gcr.io/foo robot  true} {a good} sha256:bad {gcr.io/bar robot  false} {a good}}: tag good: ERROR: tag move detected from sha256:bad to sha256:600d"
time="2021-07-29T22:45:34Z" level=error msg="edge {{gcr.io/foo robot  true} {a good} sha256:bad {gcr.io/cat robot  false} {a good}}: tag good: ERROR: tag move detected from sha256:bad to sha256:600d"
time="2021-07-29T22:45:34Z" level=info msg="Nothing to promote."
time="2021-07-29T22:45:34Z" level=info msg="edge {{gcr.io/foo robot  true} {a 0.9} sha256:000 {us.gcr.io/dog/some/subdir/path/foo robot  false} {a 0.9}}: regular promotion (neither digest nor pqin exists in dst)\n"
time="2021-07-29T22:45:34Z" level=info msg="Pending promotions:"
time="2021-07-29T22:45:34Z" level=info msg="  {{gcr.io/foo robot  true} {a 0.9} sha256:000 {us.gcr.io/dog/some/subdir/path/foo robot  false} {a 0.9}}\n"
time="2021-07-29T22:45:34Z" level=info msg="---------- BEGIN PROMOTION ----------"
time="2021-07-29T22:45:34Z" level=info msg="Request <nil>: OK\n"
... skipping 2 lines ...
time="2021-07-29T22:45:34Z" level=info msg="  {{gcr.io/foo robot  true} {a } sha256:000 {gcr.io/cat robot  false} {a }}\n"
time="2021-07-29T22:45:34Z" level=info msg="---------- BEGIN PROMOTION ----------"
time="2021-07-29T22:45:34Z" level=info msg="Request <nil>: OK\n"
time="2021-07-29T22:45:34Z" level=info msg="edge {{gcr.io/foo robot  true} {a 0.9} sha256:000 {gcr.io/bar robot  false} {a 0.9}}: skipping because it was already promoted (case 1)\n"
time="2021-07-29T22:45:34Z" level=info msg="edge {{gcr.io/foo robot  true} {a 0.9} sha256:000 {gcr.io/cat robot  false} {a 0.9}}: skipping because it was already promoted (case 1)\n"
time="2021-07-29T22:45:34Z" level=info msg="Nothing to promote."
time="2021-07-29T22:45:34Z" level=error msg="edge {{gcr.io/foo robot  true} {a missing-from-src} sha256:000 {gcr.io/bar robot  false} {a missing-from-src}}: skipping gcr.io/foo/a@sha256:000 because it is _LOST_ (can't find it in src registry!)\n"
time="2021-07-29T22:45:34Z" level=error msg="edge {{gcr.io/foo robot  true} {a missing-from-src} sha256:000 {gcr.io/cat robot  false} {a missing-from-src}}: skipping gcr.io/foo/a@sha256:000 because it is _LOST_ (can't find it in src registry!)\n"
time="2021-07-29T22:45:34Z" level=info msg="edge {{gcr.io/foo robot  true} {a 0.8} sha256:333 {gcr.io/bar robot  false} {a 0.8}}: skipping because it was already promoted (case 1)\n"
time="2021-07-29T22:45:34Z" level=error msg="edge {{gcr.io/foo robot  true} {a 0.8} sha256:333 {gcr.io/cat robot  false} {a 0.8}}: skipping gcr.io/foo/a@sha256:333 because it is _LOST_ (can't find it in src registry!)\n"
time="2021-07-29T22:45:34Z" level=error msg="edge {{gcr.io/foo robot  true} {b also-missing} sha256:bbb {gcr.io/bar robot  false} {b also-missing}}: skipping gcr.io/foo/b@sha256:bbb because it is _LOST_ (can't find it in src registry!)\n"
time="2021-07-29T22:45:34Z" level=error msg="edge {{gcr.io/foo robot  true} {b also-missing} sha256:bbb {gcr.io/cat robot  false} {b also-missing}}: skipping gcr.io/foo/b@sha256:bbb because it is _LOST_ (can't find it in src registry!)\n"
time="2021-07-29T22:45:34Z" level=info msg="Nothing to promote."
time="2021-07-29T22:45:34Z" level=info msg="edge {{gcr.io/foo robot  true} {a 0.9} sha256:000 {gcr.io/bar robot  false} {a 0.9}}: skipping because it was already promoted (case 1)\n"
time="2021-07-29T22:45:34Z" level=info msg="edge {{gcr.io/foo robot  true} {a 1.0} sha256:000 {gcr.io/bar robot  false} {a 1.0}}: digest \"sha256:000\" already exists, but does not have the pqin we want ([0.9])\n"
time="2021-07-29T22:45:34Z" level=info msg="edge {{gcr.io/foo robot  true} {a 0.9} sha256:000 {gcr.io/cat robot  false} {a 0.9}}: skipping because it was already promoted (case 1)\n"
time="2021-07-29T22:45:34Z" level=info msg="edge {{gcr.io/foo robot  true} {a 1.0} sha256:000 {gcr.io/cat robot  false} {a 1.0}}: digest \"sha256:000\" already exists, but does not have the pqin we want ([0.9])\n"
time="2021-07-29T22:45:34Z" level=info msg="Pending promotions:"
... skipping 13 lines ...
--- PASS: TestPromotion (0.00s)
=== RUN   TestExecRequests
time="2021-07-29T22:45:34Z" level=info msg="---------- BEGIN PROMOTION ----------"
time="2021-07-29T22:45:34Z" level=info msg="Request {0 gcr.io/foo gcr.io/bar robot a a sha256:000  0.9}: OK\n"
time="2021-07-29T22:45:34Z" level=info msg="Request {0 gcr.io/foo gcr.io/cat robot a a sha256:000  0.9}: OK\n"
time="2021-07-29T22:45:34Z" level=info msg="---------- BEGIN PROMOTION ----------"
time="2021-07-29T22:45:34Z" level=error msg="Request {{0 gcr.io/foo gcr.io/bar robot a a sha256:000  0.9} <nil>}: error(s) encountered: [{Running TestExecRequests This request results in an error}]\n"
time="2021-07-29T22:45:34Z" level=error msg="Request {{0 gcr.io/foo gcr.io/cat robot a a sha256:000  0.9} <nil>}: error(s) encountered: [{Running TestExecRequests This request results in an error}]\n"
--- PASS: TestExecRequests (0.00s)
=== RUN   TestGarbageCollection
time="2021-07-29T22:45:34Z" level=info msg="Request <nil>: OK\n"
time="2021-07-29T22:45:34Z" level=info msg="Request <nil>: OK\n"
--- PASS: TestGarbageCollection (0.00s)
=== RUN   TestGarbageCollectionMulti
... skipping 25 lines ...
=== RUN   TestFlush
--- PASS: TestFlush (0.00s)
=== RUN   TestRequestCounterIncrement
--- PASS: TestRequestCounterIncrement (0.00s)
=== RUN   TestCycle
    reqcounter_test.go:159: 
        	Error Trace:	reqcounter_test.go:159
        	Error:      	Not equal: 
        	            	expected: []string{"From 2006-01-02 15:04:05 to 2006-01-02 15:04:08 [0 min] there have been 82 requests to GCR.", "From 2006-01-02 15:04:08 to 2006-01-02 15:04:11 [0 min] there have been 0 requests to GCR.", "From 2006-01-02 15:04:11 to 2006-01-02 15:04:14 [0 min] there have been 0 requests to GCR.", "From 2006-01-02 15:04:14 to 2006-01-02 15:04:17 [0 min] there have been 0 requests to GCR.", "From 2006-01-02 15:04:17 to 2006-01-02 15:04:20 [0 min] there have been 0 requests to GCR."}
        	            	actual  : []string{"From 2006-01-02 15:04:05 to 2006-01-02 15:04:05 [0 min] there have been 82 requests to GCR.", "From 2006-01-02 15:04:05 to 2006-01-02 15:04:05 [0 min] there have been 0 requests to GCR.", "From 2006-01-02 15:04:05 to 2006-01-02 15:04:05 [0 min] there have been 0 requests to GCR.", "From 2006-01-02 15:04:05 to 2006-01-02 15:04:05 [0 min] there have been 0 requests to GCR.", "From 2006-01-02 15:04:05 to 2006-01-02 15:04:05 [0 min] there have been 0 requests to GCR."}
        	            	
        	            	Diff:
        	            	--- Expected
        	            	+++ Actual
... skipping 9 lines ...
        	            	+ (string) (len=90) "From 2006-01-02 15:04:05 to 2006-01-02 15:04:05 [0 min] there have been 0 requests to GCR.",
        	            	+ (string) (len=90) "From 2006-01-02 15:04:05 to 2006-01-02 15:04:05 [0 min] there have been 0 requests to GCR.",
        	            	+ (string) (len=90) "From 2006-01-02 15:04:05 to 2006-01-02 15:04:05 [0 min] there have been 0 requests to GCR."
        	            	 }
        	Test:       	TestCycle
        	Messages:   	The request counter produced malformed logs.
--- FAIL: TestCycle (0.00s)
FAIL
coverage: 92.0% of statements
FAIL	sigs.k8s.io/k8s-container-image-promoter/legacy/reqcounter	0.016s
?   	sigs.k8s.io/k8s-container-image-promoter/legacy/stream	[no test files]
?   	sigs.k8s.io/k8s-container-image-promoter/legacy/timewrapper	[no test files]
FAIL
make[1]: *** [Makefile:71: test-go-unit] Error 1
make[1]: Leaving directory '/home/prow/go/src/sigs.k8s.io/k8s-container-image-promoter'
make: *** [Makefile:75: test-ci] Error 2