1123706 - proxxy uses a log level of ERROR for download_file() even though it retries (resulting in log parser false positives against "Caught exception: HTTP Error 404: Not Found")

Status: RESOLVED FIXED

(Release Engineering :: Applications: MozharnessCore, defect)

Description

[Ed Morley [:emorley]]

eg:
https://treeherder.mozilla.org/logviewer.html#?job_id=4289493&repo=try

17:09:33 INFO - proxxy config: {'regions': ['.use1.', '.usw2.'], 'instances': ['proxxy1.srv.releng.use1.mozilla.com', 'proxxy1.srv.releng.usw2.mozilla.com'], 'urls': [('http://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp-ssl.mozilla.org', 'ftp.mozilla.org'), ('http://pvtbuilds.pvt.build.mozilla.org', 'pvtbuilds.mozilla.org'), ('http://tooltool.pvt.build.mozilla.org', 'tooltool.pvt.build.mozilla.org'), ('http://pypi.pvt.build.mozilla.org', 'pypi.pvt.build.mozilla.org'), ('http://pypi.pub.build.mozilla.org', 'pypi.pub.build.mozilla.org')]}
17:09:33 INFO - http://tooltool.pvt.build.mozilla.org/build/sha512/263f4e8796c25543f64ba36e53d5c4ab8ed4d4e919226037ac0988761d34791b038ce96a8ae434f0153f9c2061204086decdbff18bdced42f3849156ae4dc9a4 matches http://tooltool.pvt.build.mozilla.org
17:09:33 INFO - URL Candidate: http://tooltool.pvt.build.mozilla.org.proxxy1.srv.releng.use1.mozilla.com/build/sha512/263f4e8796c25543f64ba36e53d5c4ab8ed4d4e919226037ac0988761d34791b038ce96a8ae434f0153f9c2061204086decdbff18bdced42f3849156ae4dc9a4
17:09:33 INFO - trying http://tooltool.pvt.build.mozilla.org.proxxy1.srv.releng.use1.mozilla.com/build/sha512/263f4e8796c25543f64ba36e53d5c4ab8ed4d4e919226037ac0988761d34791b038ce96a8ae434f0153f9c2061204086decdbff18bdced42f3849156ae4dc9a4
17:09:33 INFO - Downloading http://tooltool.pvt.build.mozilla.org.proxxy1.srv.releng.use1.mozilla.com/build/sha512/263f4e8796c25543f64ba36e53d5c4ab8ed4d4e919226037ac0988761d34791b038ce96a8ae434f0153f9c2061204086decdbff18bdced42f3849156ae4dc9a4 to /builds/slave/test/build/263f4e8796c25543f64ba36e53d5c4ab8ed4d4e919226037ac0988761d34791b038ce96a8ae434f0153f9c2061204086decdbff18bdced42f3849156ae4dc9a4
17:09:33 INFO - retry: Calling _download_file with args: ('http://tooltool.pvt.build.mozilla.org.proxxy1.srv.releng.use1.mozilla.com/build/sha512/263f4e8796c25543f64ba36e53d5c4ab8ed4d4e919226037ac0988761d34791b038ce96a8ae434f0153f9c2061204086decdbff18bdced42f3849156ae4dc9a4', '/builds/slave/test/build/263f4e8796c25543f64ba36e53d5c4ab8ed4d4e919226037ac0988761d34791b038ce96a8ae434f0153f9c2061204086decdbff18bdced42f3849156ae4dc9a4'), kwargs: {}, attempt #1
17:09:34 WARNING - Server returned status 404 HTTP Error 404: Not Found for http://tooltool.pvt.build.mozilla.org.proxxy1.srv.releng.use1.mozilla.com/build/sha512/263f4e8796c25543f64ba36e53d5c4ab8ed4d4e919226037ac0988761d34791b038ce96a8ae434f0153f9c2061204086decdbff18bdced42f3849156ae4dc9a4
17:09:34 INFO - retry: Failed, sleeping 30 seconds before retrying
17:10:04 INFO - retry: Calling _download_file with args: ('http://tooltool.pvt.build.mozilla.org.proxxy1.srv.releng.use1.mozilla.com/build/sha512/263f4e8796c25543f64ba36e53d5c4ab8ed4d4e919226037ac0988761d34791b038ce96a8ae434f0153f9c2061204086decdbff18bdced42f3849156ae4dc9a4', '/builds/slave/test/build/263f4e8796c25543f64ba36e53d5c4ab8ed4d4e919226037ac0988761d34791b038ce96a8ae434f0153f9c2061204086decdbff18bdced42f3849156ae4dc9a4'), kwargs: {}, attempt #2
17:10:04 WARNING - Server returned status 404 HTTP Error 404: Not Found for http://tooltool.pvt.build.mozilla.org.proxxy1.srv.releng.use1.mozilla.com/build/sha512/263f4e8796c25543f64ba36e53d5c4ab8ed4d4e919226037ac0988761d34791b038ce96a8ae434f0153f9c2061204086decdbff18bdced42f3849156ae4dc9a4
17:10:04 INFO - retry: Failed, sleeping 60 seconds before retrying
17:11:04 INFO - retry: Calling _download_file with args: ('http://tooltool.pvt.build.mozilla.org.proxxy1.srv.releng.use1.mozilla.com/build/sha512/263f4e8796c25543f64ba36e53d5c4ab8ed4d4e919226037ac0988761d34791b038ce96a8ae434f0153f9c2061204086decdbff18bdced42f3849156ae4dc9a4', '/builds/slave/test/build/263f4e8796c25543f64ba36e53d5c4ab8ed4d4e919226037ac0988761d34791b038ce96a8ae434f0153f9c2061204086decdbff18bdced42f3849156ae4dc9a4'), kwargs: {}, attempt #3
17:11:04 WARNING - Server returned status 404 HTTP Error 404: Not Found for http://tooltool.pvt.build.mozilla.org.proxxy1.srv.releng.use1.mozilla.com/build/sha512/263f4e8796c25543f64ba36e53d5c4ab8ed4d4e919226037ac0988761d34791b038ce96a8ae434f0153f9c2061204086decdbff18bdced42f3849156ae4dc9a4
17:11:04 ERROR - Can't download from http://tooltool.pvt.build.mozilla.org.proxxy1.srv.releng.use1.mozilla.com/build/sha512/263f4e8796c25543f64ba36e53d5c4ab8ed4d4e919226037ac0988761d34791b038ce96a8ae434f0153f9c2061204086decdbff18bdced42f3849156ae4dc9a4 to /builds/slave/test/build/263f4e8796c25543f64ba36e53d5c4ab8ed4d4e919226037ac0988761d34791b038ce96a8ae434f0153f9c2061204086decdbff18bdced42f3849156ae4dc9a4!
17:11:04 ERROR - Caught exception: HTTP Error 404: Not Found
17:11:04 ERROR - Caught exception: HTTP Error 404: Not Found
17:11:04 ERROR - Caught exception: HTTP Error 404: Not Found
17:11:04 INFO - trying http://tooltool.pvt.build.mozilla.org/build/sha512/263f4e8796c25543f64ba36e53d5c4ab8ed4d4e919226037ac0988761d34791b038ce96a8ae434f0153f9c2061204086decdbff18bdced42f3849156ae4dc9a4
17:11:04 INFO - Downloading http://tooltool.pvt.build.mozilla.org/build/sha512/263f4e8796c25543f64ba36e53d5c4ab8ed4d4e919226037ac0988761d34791b038ce96a8ae434f0153f9c2061204086decdbff18bdced42f3849156ae4dc9a4 to /builds/slave/test/build/263f4e8796c25543f64ba36e53d5c4ab8ed4d4e919226037ac0988761d34791b038ce96a8ae434f0153f9c2061204086decdbff18bdced42f3849156ae4dc9a4
17:11:04 INFO - retry: Calling _download_file with args: ('http://tooltool.pvt.build.mozilla.org/build/sha512/263f4e8796c25543f64ba36e53d5c4ab8ed4d4e919226037ac0988761d34791b038ce96a8ae434f0153f9c2061204086decdbff18bdced42f3849156ae4dc9a4', '/builds/slave/test/build/263f4e8796c25543f64ba36e53d5c4ab8ed4d4e919226037ac0988761d34791b038ce96a8ae434f0153f9c2061204086decdbff18bdced42f3849156ae4dc9a4'), kwargs: {}, attempt #1
17:11:07 INFO - Downloaded 25485212 bytes. 


All three of these lines should have been given log level INFO instead:

17:11:04 ERROR - Can't download from http://tooltool.pvt.build.mozilla.org.proxxy1.srv.releng.use1.mozilla.com/build/sha512/<snip> to /builds/slave/test/build/<snip>!
17:11:04 ERROR - Caught exception: HTTP Error 404: Not Found
17:11:04 ERROR - Caught exception: HTTP Error 404: Not Found
17:11:04 ERROR - Caught exception: HTTP Error 404: Not Found

This is causing false positives in the Treeherder failure summary.

Comment 1

[Ed Morley [:emorley]]

Attachment: Make proxxy use an error_level of INFO for download retries

proxxy attempts to download a file three times from each proxy URL, before
moving onto the next. There is already handling in case all proxy URLS have been
tried and the download was not successful - so it's not correct to use a log
level of ERROR for each attempt leading up to that point, since one URL may 404
but the next succeed.

Comment 2

[Ed Morley [:emorley]]

Thanks :-)

https://hg.mozilla.org/build/mozharness/rev/5d5a82e8f502

Comment 3

[Ed Morley [:emorley]]

This still seems to be happening:
https://treeherder.mozilla.org/logviewer.html#?job_id=911362&repo=mozilla-central

I'll investigate more tomorrow.

Comment 4

[Ed Morley [:emorley]]

Actually that was using mozharness 32ad9a83a641, which was before this landed. New jobs are fine.