Hide Forgot
Description of problem: Synced rhel6_x86_64 with Katello. Mid way through sync I stopped Pulp/Katello. Then resumed later. I am seeing many messages of: 2011-11-09 12:35:11,491 27332:140325469247232: grinder.ProgressTracker:ERROR: ProgressTracker:207 Negative delta_bytes <-7240924.0>. download_total=<11819836.0>, downloaded=<15968.0>, prev_remaining_bytes=<4562944.0>, remaining_bytes=<11803868.0>, total_size_bytes=<11819836.0>, https://cdn.redhat.com/content/dist/rhel/server/6/6.1/x86_64/os/Packages/kdelibs-4.3.4-11.el6_0.2.i686.rpm 2011-11-09 12:35:11,493 27332:140325469247232: grinder.ProgressTracker:ERROR: ProgressTracker:207 Negative delta_bytes <-7237712.0>. download_total=<11819836.0>, downloaded=<19180.0>, prev_remaining_bytes=<4562944.0>, remaining_bytes=<11800656.0>, total_size_bytes=<11819836.0>, https://cdn.redhat.com/content/dist/rhel/server/6/6.1/x86_64/os/Packages/kdelibs-4.3.4-11.el6_0.2.i686.rpm More of the log snippet from grinder below 2011-11-09 12:35:05,259 27332:140325469247232: grinder.ParallelFetch:INFO: ParallelFetch:138 4 threads are active. 3638 items left to be fetched 2011-11-09 12:35:05,310 27332:140325093893888: grinder.BaseFetch:INFO: activeobject:160 A partial download file already exists; prepare to resume download. 2011-11-09 12:35:05,319 27332:140325469247232: grinder.ParallelFetch:INFO: ParallelFetch:138 4 threads are active. 3637 items left to be fetched 2011-11-09 12:35:05,687 27332:140325093893888: grinder.BaseFetch:INFO: activeobject:160 Fetching 49082348 bytes: kdebase-workspace-wallpapers-4.3.4-19.el6.noarch.rpm from https://cdn.redhat.com/content/dist/rhel/server/6/6.1/x86_64/os/P ackages/kdebase-workspace-wallpapers-4.3.4-19.el6.noarch.rpm 2011-11-09 12:35:05,692 27332:140325469247232: grinder.ParallelFetch:INFO: ParallelFetch:138 4 threads are active. 3636 items left to be fetched 2011-11-09 12:35:05,703 27332:140325469247232: grinder.ParallelFetch:INFO: ParallelFetch:138 4 threads are active. 3635 items left to be fetched 2011-11-09 12:35:05,710 27332:140325469247232: grinder.ParallelFetch:INFO: ParallelFetch:138 4 threads are active. 3634 items left to be fetched 2011-11-09 12:35:05,765 27332:140325458757376: grinder.BaseFetch:INFO: activeobject:160 A partial download file already exists; prepare to resume download. 2011-11-09 12:35:05,766 27332:140325458757376: grinder.BaseFetch:INFO: activeobject:160 Fetching 42926128 bytes: kdegames-4.3.4-5.el6.x86_64.rpm from https://cdn.redhat.com/content/dist/rhel/server/6/6.1/x86_64/os/Packages/kdegames-4.3.4-5.el6.x86_64.rpm 2011-11-09 12:35:05,770 27332:140325104383744: grinder.ParallelFetch:INFO: ParallelFetch:138 4 threads are active. 3633 items left to be fetched 2011-11-09 12:35:05,770 27332:140325469247232: grinder.ParallelFetch:INFO: ParallelFetch:138 4 threads are active. 3632 items left to be fetched 2011-11-09 12:35:05,779 27332:140325469247232: grinder.BaseFetch:INFO: activeobject:160 A partial download file already exists; prepare to resume download. 2011-11-09 12:35:05,780 27332:140325469247232: grinder.BaseFetch:INFO: activeobject:160 Fetching 11819836 bytes: kdelibs-4.3.4-11.el6_0.2.i686.rpm from https://cdn.redhat.com/content/dist/rhel/server/6/6.1/x86_64/os/Packages/kdelibs-4.3.4-11.el6_0.2.i686.rpm 2011-11-09 12:35:05,825 27332:140325104383744: grinder.ParallelFetch:INFO: ParallelFetch:138 4 threads are active. 3631 items left to be fetched 2011-11-09 12:35:05,850 27332:140325104383744: grinder.BaseFetch:INFO: activeobject:160 Fetching 11697272 bytes: kdelibs-4.3.4-11.el6_0.2.x86_64.rpm from https://cdn.redhat.com/content/dist/rhel/server/6/6.1/x86_64/os/Packages/kdelibs-4.3.4-11.el6_0.2.x86_64.rpm 2011-11-09 12:35:06,978 27332:140325093893888: grinder.ProgressTracker:WARNING: ProgressTracker:126 Modifying size information for <https://cdn.redhat.com/content/dist/rhel/server/6/6.1/x86_64/os/Packages/kdebase-workspace-wallpapers-4.3.4-19.el6.noarch.rpm>. original size = <49082348>, new size = <19845100.0>, diff_in_size = <-29237248.0> 2011-11-09 12:35:07,575 27332:140325458757376: grinder.ProgressTracker:WARNING: ProgressTracker:126 Modifying size information for <https://cdn.redhat.com/content/dist/rhel/server/6/6.1/x86_64/os/Packages/kdegames-4.3.4-5.el6.x86_64.rpm>. original size = <42926128>, new size = <12681264.0>, diff_in_size = <-30244864.0> 2011-11-09 12:35:08,614 27332:140325469247232: grinder.ProgressTracker:WARNING: ProgressTracker:126 Modifying size information for <https://cdn.redhat.com/content/dist/rhel/server/6/6.1/x86_64/os/Packages/kdelibs-4.3.4-11.el6_0.2.i686.rpm>. original size = <11819836>, new size = <7256892.0>, diff_in_size = <-4562944.0> 2011-11-09 12:35:10,842 27332:140325469247232: grinder.BaseFetch:WARNING: activeobject:160 Retrying fetch of: kdelibs-4.3.4-11.el6_0.2.i686.rpm with 1 retry attempts left. 2011-11-09 12:35:10,844 27332:140325469247232: grinder.BaseFetch:INFO: activeobject:160 Fetching 11819836 bytes: kdelibs-4.3.4-11.el6_0.2.i686.rpm from https://cdn.redhat.com/content/dist/rhel/server/6/6.1/x86_64/os/Packages/kdelibs-4.3.4-11.el6_0.2.i686.rpm 2011-11-09 12:35:11,255 27332:140325104383744: grinder.BaseFetch:INFO: activeobject:160 Create a link in repo directory for the package at /var/lib/pulp//repos/ACME_Corporation/Locker/Red_Hat_Enterprise_Linux_Server/Red_Hat_Enterprise_Linux_6_Server_RPMs_61_x86_64//Packages/kdelibs-4.3.4-11.el6_0.2.x86_64.rpm to ../../../../../../packages/kdelibs/4.3.4/11.el6_0.2/x86_64/e57/kdelibs-4.3.4-11.el6_0.2.x86_64.rpm 2011-11-09 12:35:11,294 27332:140325458757376: grinder.BaseFetch:WARNING: activeobject:160 Retrying fetch of: kdegames-4.3.4-5.el6.x86_64.rpm with 1 retry attempts left. 2011-11-09 12:35:11,324 27332:140325469247232: grinder.ProgressTracker:WARNING: ProgressTracker:126 Modifying size information for <https://cdn.redhat.com/content/dist/rhel/server/6/6.1/x86_64/os/Packages/kdelibs-4.3.4-11.el6_0.2.i686.rpm>. original size = <7256892.0>, new size = <11819836.0>, diff_in_size = <4562944.0> 2011-11-09 12:35:11,491 27332:140325469247232: grinder.ProgressTracker:ERROR: ProgressTracker:207 Negative delta_bytes <-7240924.0>. download_total=<11819836.0>, downloaded=<15968.0>, prev_remaining_bytes=<4562944.0>, remaining_bytes=<11803868.0>, total_size_bytes=<11819836.0>, https://cdn.redhat.com/content/dist/rhel/server/6/6.1/x86_64/os/Packages/kdelibs-4.3.4-11.el6_0.2.i686.rpm 2011-11-09 12:35:11,493 27332:140325469247232: grinder.ProgressTracker:ERROR: ProgressTracker:207 Negative delta_bytes <-7237712.0>. download_total=<11819836.0>, downloaded=<19180.0>, prev_remaining_bytes=<4562944.0>, remaining_bytes=<11800656.0>, total_size_bytes=<11819836.0>, https://cdn.redhat.com/content/dist/rhel/server/6/6.1/x86_64/os/Packages/kdelibs-4.3.4-11.el6_0.2.i686.rpm 2011-11-09 12:35:11,495 27332:140325469247232: grinder.ProgressTracker:ERROR: ProgressTracker:207 Negative delta_bytes <-7221328.0>. download_total=<11819836.0>, downloaded=<35564.0>, prev_remaining_bytes=<4562944.0>, remaining_bytes=<11784272.0>, total_size_bytes=<11819836.0>, https://cdn.redhat.com/content/dist/rhel/server/6/6.1/x86_64/os/Packages/kdelibs-4.3.4-11.el6_0.2.i686.rpm 2011-11-09 12:35:11,497 27332:140325104383744: grinder.ParallelFetch:INFO: ParallelFetch:138 4 threads are active. 3630 items left to be fetched 2011-11-09 12:35:11,497 27332:140325469247232: grinder.ProgressTracker:ERROR: ProgressTracker:207 Negative delta_bytes <-7217352.0>. download_total=<11819836.0>, downloaded=<39540.0>, prev_remaining_bytes=<4562944.0>, remaining_bytes=<11780296.0>, total_size_bytes=<11819836.0>, https://cdn.redhat.com/content/dist/rhel/server/6/6.1/x86_64/os/Packages/kdelibs-4.3.4-11.el6_0.2.i686.rpm QE Test is to 1) Sync a repo 2) Interrupt/Cancel the Sync 3) Resume Sync 4) Look at grinder logs, you should not see these messages for RPMs: grinder.ProgressTracker:ERROR: ProgressTracker:207 Negative delta_bytes Note: You will may see those messages for distribution files if the metadata is incorrect from the server, we have been seeing this for rhel6.
Two issues: 1) Resuming a partial download caused a refetch. We weren't handling the return HTTP code, so the partial download was being completed then discarded and we'd refetch. 2) We weren't handling refetches as described in bz 765930 Commit for #1 below http://git.fedorahosted.org/git/?p=grinder.git;a=commitdiff;h=4b2670430dff269837e396c6822679ae8269e283 See 765930 for commit for the refetch. QE: When you do resume a sync, look in grinder logs and verify that the resumed file successfully resumes. If it resumes, then drops the same file and refetches this issue is not fixed.
build: 0.255
Fails_qa [root@preethi ~]# rpm -q pulp pulp-0.0.255-1.fc15.noarch [root@preethi ~]# with resumed sync I still see the following messages in grinder.log 2011-12-20 14:54:53,114 6961:139681362589440: grinder.ProgressTracker:ERROR: ProgressTracker:207 Negative delta_bytes <-107904.0>. download_total=<334356.0>, downloaded=<23168.0>, prev_remaining_bytes=<203284.0>, remaining_bytes=<311188.0>, total_size_bytes=<334356.0>, http://download.devel.redhat.com/released/F-16/GOLD/Fedora/x86_64/os/Packages/eclipse-callgraph-0.8.0-1.fc16.x86_64.rpm 2011-12-20 14:54:53,117 6961:139681362589440: grinder.ProgressTracker:ERROR: ProgressTracker:207 Negative delta_bytes <-100664.0>. download_total=<334356.0>, downloaded=<30408.0>, prev_remaining_bytes=<203284.0>, remaining_bytes=<303948.0>, total_size_bytes=<334356.0>, http://download.devel.redhat.com/released/F-16/GOLD/Fedora/x86_64/os/Packages/eclipse-callgraph-0.8.0-1.fc16.x86_64.rpm 2011-12-20 14:54:53,119 6961:139681362589440: grinder.ProgressTracker:ERROR: ProgressTracker:207 Negative delta_bytes <-94872.0>. download_total=<334356.0>, downloaded=<36200.0>, prev_remaining_bytes=<203284.0>, remaining_bytes=<298156.0>, total_size_bytes=<334356.0>, http://download.devel.redhat.com/released/F-16/GOLD/Fedora/x86_64/os/Packages/eclipse-callgraph-0.8.0-1.fc16.x86_64.rpm 2011-12-20 14:54:53,131 6961:139681949783808: grinder.ProgressTracker:ERROR: ProgressTracker:207 Negative delta_bytes <-106616.0>. download_total=<131800.0>, downloaded=<2896.0>, prev_remaining_bytes=<22288.0>, remaining_bytes=<128904.0>, total_size_bytes=<131800.0>, http://download.devel.redhat.com/released/F-16/GOLD/Fedora/x86_64/os/Packages/sil-gentium-basic-book-fonts-1.1-6.fc15.noarch.rpm 2011-12-20 14:54:53,131 6961:139681949783808: grinder.ProgressTracker:ERROR: ProgressTracker:207 Negative delta_bytes <-106616.0>. download_total=<131800.0>, downloaded=<2896.0>, prev_remaining_bytes=<22288.0>, remaining_bytes=<128904.0>, total_size_bytes=<131800.0>, http://download.devel.redhat.com/released/F-16/GOLD/Fedora/x86_64/os/Packages/sil-gentium-basic-book-fonts-1.1-6.fc15.noarch.rpm
I believe the problem is that we were using an older Grinder when QE tested this. I made a mistake and did not bump the pulp.spec correctly to require Grinder 0.134 or newer, so grinder 0.128 was part of the QE build which didn't have the fix needed. Below change fixes this so Pulp now requires Grinder 0.136 http://git.fedorahosted.org/git/?p=pulp.git;a=commitdiff;h=548ad62d61d1b47cf079fa91ec5a713827681f0d QE: Please re-test with Grinder 0.136
build: 0.256
verified [root@preethi ~]# rpm -q pulp pulp-0.0.256-1.fc15.noarch [root@preethi ~]# 2012-01-06 14:58:57,037 25671:140401194256128: grinder.ParallelFetch:INFO: ParallelFetch:191 Told thread <<WorkerThread(Thread-101, started daemon 140400685717248)>> to stop 2012-01-06 14:58:57,038 25671:140401194256128: grinder.ParallelFetch:INFO: ParallelFetch:271 stop() invoked 2012-01-06 14:58:57,041 25671:140400132093696: grinder.ParallelFetch:INFO: ParallelFetch:308 WorkerThread deleting ActiveObject 2012-01-06 14:58:57,041 25671:140401194256128: grinder.ParallelFetch:INFO: ParallelFetch:281 stop() completed 2012-01-06 14:58:57,041 25671:140400132093696: grinder.ParallelFetch:INFO: ParallelFetch:323 Thread ending 2012-01-06 14:58:57,041 25671:140401194256128: grinder.ParallelFetch:INFO: ParallelFetch:191 Told thread <<WorkerThread(Thread-102, started daemon 140400132093696)>> to stop 2012-01-06 14:58:57,042 25671:140401194256128: grinder.ParallelFetch:INFO: ParallelFetch:271 stop() invoked 2012-01-06 14:58:57,044 25671:140400123700992: grinder.ParallelFetch:INFO: ParallelFetch:308 WorkerThread deleting ActiveObject 2012-01-06 14:58:57,045 25671:140401194256128: grinder.ParallelFetch:INFO: ParallelFetch:281 stop() completed 2012-01-06 14:58:57,045 25671:140400123700992: grinder.ParallelFetch:INFO: ParallelFetch:323 Thread ending
Pulp v1.0 is released Closed Current Release.
Pulp v1.0 is released.