Attachment 835680 Details for Bug 1040739 – grinder patch test log

grinder patch test log

patch_test.log (text/plain), 14.13 KB, created by mkovacik on 2013-12-12 09:13:36 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: mkovacik

Created: 2013-12-12 09:13:36 UTC

Size: 14.13 KB

patch

obsolete

># pulp.log
>
>2013-12-12 03:19:23,322 7277:140452734953216: pulp.server.api.repo_sync:INFO: repo_sync:254 Sync invoked for repo <rhel-6-server-rhui-rpms-6Server-x86_64>
>2013-12-12 03:19:23,589 7277:140452734953216: pulp.server.api.repo_sync:INFO: repo_sync:268 Sync of rhel-6-server-rhui-rpms-6Server-x86_64 starting, skip_dict = {}
>2013-12-12 03:19:24,128 7277:140452734953216: pulp.server.api.synchronizers:INFO: synchronizers:741 cacert = </etc/pki/pulp/content/rhel-6-server-rhui-rpms-6Server-x86_64/feed-rhel-6-server-rhui-rpms-6Server-x86_64.ca>, cert = </etc/pki/pulp/content/rhel-6-server-rhui-rpms-6Server-x86_64/feed-rhel-6-server-rhui-rpms-6Server-x86_64.cert>
>2013-12-12 03:19:24,128 7277:140452734953216: pulp.server.api.synchronizers:INFO: synchronizers:790 Fetching repo to </var/lib/pulp//repos/content/dist/rhel/rhui/server/6/6Server/x86_64/os> with verify_options <{'checksum': False, 'size': False}>
>2013-12-12 03:21:47,514 7277:140452734953216: pulp.server.api.synchronizers:INFO: synchronizers:798 YumSynchronizer reported 12047 successes, 0 downloads, 0 errors
>2013-12-12 03:27:11,999 7277:140452734953216: pulp.server.api.synchronizers:INFO: synchronizers:825 preserve metadata flag is set; skipping metadata update
>2013-12-12 03:27:12,273 7277:140452734953216: pulp.server.api.synchronizers:INFO: synchronizers:440 No image files to import to repo..
>2013-12-12 03:27:12,955 7277:140452734953216: pulp.server.api.synchronizers:INFO: synchronizers:420 No metadata for 'File Sync' present; no files to import to repo..
>2013-12-12 03:27:13,619 7277:140452734953216: pulp.server.api.synchronizers:INFO: synchronizers:383 Loading comps group info from: /var/lib/pulp//repos/content/dist/rhel/rhui/server/6/6Server/x86_64/os/repodata/877f91138d7aa17294b02f547bc340f217a821bf-comps-rhel-x86_64-server-6.xml
>2013-12-12 03:27:13,770 7277:140452734953216: pulp.server.api.synchronizers:INFO: synchronizers:405 updateinfo is found in repomd.xml, it's path is /var/lib/pulp//repos/content/dist/rhel/rhui/server/6/6Server/x86_64/os/repodata/67c9e1f15b11aeef697fa305bc435b9ec72700b06eaf8149b66ebd1d052f6b44-updateinfo.xml.gz
>2013-12-12 03:27:33,346 7277:140452734953216: pulp.server.api.repo_sync:INFO: repo_sync:275 Sync returned 12047 packages, 2240 errata in 489.756069899 seconds
>2013-12-12 03:27:33,670 7277:140452734953216: pulp.server.api.repo_sync:INFO: repo_sync:286 0 old packages to process, 0 new packages to process
>2013-12-12 03:27:36,921 7277:140452734953216: pulp.server.api.repo_sync:INFO: repo_sync:301 Examining 2240 errata from repo rhel-6-server-rhui-rpms-6Server-x86_64
>2013-12-12 03:27:39,495 7277:140452734953216: pulp.server.api.repo_sync:INFO: repo_sync:305 Removing 0 old errata from repo rhel-6-server-rhui-rpms-6Server-x86_64
>2013-12-12 03:27:40,760 7277:140452734953216: pulp.server.api.repo_sync:INFO: repo_sync:314 Adding 0 new errata to repo rhel-6-server-rhui-rpms-6Server-x86_64
>2013-12-12 03:27:41,325 7277:140452734953216: pulp.server.tasking.task:INFO: task:460 Task succeeded: Task 1b76a259-6306-11e3-881f-22000afc058d: _sync(rhel-6-server-rhui-rpms-6Server-x86_64, synchronizer=<pulp.server.api.synchronizers.YumSynchronizer object at 0x7fbdeb8dcdd0>, skip={}, max_speed=None, threads=None, progress_callback=<bound method RepoSyncTask.progress_callback of <pulp.server.api.repo_sync_task.RepoSyncTask object at 0x7fbdeb8dc850>>)
>
># grinder.log
>2013-12-12 03:19:24,128 7277:140452734953216: grinder.RepoFetch:INFO: RepoFetch:125 fetchYumRepo() repo_label = , repo_url = https://cdn.redhat.com//content/dist/rhel/rhui/server/6/6Server/x86_64/os, basepath = /var/lib/pulp//repos/content/dist/rhel/rhui/server/6/6Server/x86_64/os, verify_options = {'checksum': False, 'size': False}
>2013-12-12 03:19:24,129 7277:140452734953216: grinder.RepoFetch:INFO: RepoFetch:129 , https://cdn.redhat.com//content/dist/rhel/rhui/server/6/6Server/x86_64/os, Calling RepoFetch with: cacert=</etc/pki/pulp/content/rhel-6-server-rhui-rpms-6Server-x86_64/feed-rhel-6-server-rhui-rpms-6Server-x86_64.ca>, clicert=</etc/pki/pulp/content/rhel-6-server-rhui-rpms-6Server-x86_64/feed-rhel-6-server-rhui-rpms-6Server-x86_64.cert>, clikey=<None>, proxy_url=<None>, proxy_port=<None>, proxy_user=<None>, proxy_pass=<NOT_LOGGED>, sslverify=<1>, max_speed=<0>, verify_options=<{'checksum': False, 'size': False}>
>2013-12-12 03:19:24,369 7277:140452734953216: grinder.DistroInfo:INFO: DistroInfo:55 Preparing to fetch any available trees..
>2013-12-12 03:19:24,559 7277:140452734953216: grinder.BaseFetch:INFO: activeobject:160 Fetching Unknown bytes: .treeinfo from https://cdn.redhat.com//content/dist/rhel/rhui/server/6/6Server/x86_64/os/.treeinfo
>2013-12-12 03:19:26,107 7277:140452734953216: grinder.BaseFetch:WARNING: activeobject:160 Retrying fetch of: .treeinfo with 1 retry attempts left. HTTP status was 404
>2013-12-12 03:19:26,109 7277:140452734953216: grinder.BaseFetch:INFO: activeobject:160 Fetching Unknown bytes: .treeinfo from https://cdn.redhat.com//content/dist/rhel/rhui/server/6/6Server/x86_64/os/.treeinfo
>2013-12-12 03:19:26,683 7277:140452734953216: grinder.BaseFetch:WARNING: activeobject:160 Retrying fetch of: .treeinfo with 0 retry attempts left. HTTP status was 404
>2013-12-12 03:19:26,684 7277:140452734953216: grinder.BaseFetch:INFO: activeobject:160 Fetching Unknown bytes: .treeinfo from https://cdn.redhat.com//content/dist/rhel/rhui/server/6/6Server/x86_64/os/.treeinfo
>2013-12-12 03:19:27,261 7277:140452734953216: grinder.BaseFetch:WARNING: activeobject:160 ERROR: Response = 404 fetching https://cdn.redhat.com//content/dist/rhel/rhui/server/6/6Server/x86_64/os/.treeinfo.
>2013-12-12 03:19:27,265 7277:140452734953216: grinder.BaseFetch:INFO: activeobject:160 Fetching Unknown bytes: treeinfo from https://cdn.redhat.com//content/dist/rhel/rhui/server/6/6Server/x86_64/os/treeinfo
>2013-12-12 03:19:28,375 7277:140452734953216: grinder.BaseFetch:WARNING: activeobject:160 Retrying fetch of: treeinfo with 1 retry attempts left. HTTP status was 404
>2013-12-12 03:19:28,377 7277:140452734953216: grinder.BaseFetch:INFO: activeobject:160 Fetching Unknown bytes: treeinfo from https://cdn.redhat.com//content/dist/rhel/rhui/server/6/6Server/x86_64/os/treeinfo
>2013-12-12 03:19:28,977 7277:140452734953216: grinder.BaseFetch:WARNING: activeobject:160 Retrying fetch of: treeinfo with 0 retry attempts left. HTTP status was 404
>2013-12-12 03:19:28,979 7277:140452734953216: grinder.BaseFetch:INFO: activeobject:160 Fetching Unknown bytes: treeinfo from https://cdn.redhat.com//content/dist/rhel/rhui/server/6/6Server/x86_64/os/treeinfo
>2013-12-12 03:19:29,551 7277:140452734953216: grinder.BaseFetch:WARNING: activeobject:160 ERROR: Response = 404 fetching https://cdn.redhat.com//content/dist/rhel/rhui/server/6/6Server/x86_64/os/treeinfo.
>2013-12-12 03:19:29,552 7277:140452734953216: grinder.DistroInfo:INFO: DistroInfo:84 Unable to read the tree info config.
>2013-12-12 03:19:29,553 7277:140452734953216: grinder.DistroInfo:INFO: DistroInfo:85 [Errno 2] No such file or directory: u'/var/lib/pulp//repos/content/dist/rhel/rhui/server/6/6Server/x86_64/os/treeinfo'
>2013-12-12 03:19:29,775 7277:140452734953216: grinder.YumInfo:INFO: activeobject:160 repo_dir='/var/lib/pulp//repos/content/dist/rhel/rhui/server/6/6Server/x86_64/os/', packages_location='/var/lib/pulp//packages', skip='{}', newest='False', remove_old='False', numOldPackages='2'
>2013-12-12 03:20:15,944 7277:140452734953216: grinder.YumInfo:INFO: activeobject:160 12047 packages have been marked to be fetched
>2013-12-12 03:20:30,679 7277:140452734953216: grinder.ParallelFetch:INFO: ParallelFetch:176 12047 items are marked to be fetched
>2013-12-12 03:20:30,944 7277:140452724463360: grinder.ParallelFetch:INFO: ParallelFetch:137 4 threads are active. 12047 items left to be fetched
>2013-12-12 03:20:30,947 7277:140452724463360: grinder.ParallelFetch:INFO: ParallelFetch:137 4 threads are active. 12046 items left to be fetched
>2013-12-12 03:20:30,950 7277:140452713973504: grinder.ParallelFetch:INFO: ParallelFetch:137 4 threads are active. 12045 items left to be fetched
>2013-12-12 03:20:30,959 7277:140452713973504: grinder.ParallelFetch:INFO: ParallelFetch:137 4 threads are active. 12044 items left to be fetched
>2013-12-12 03:20:30,960 7277:140452724463360: grinder.ParallelFetch:INFO: ParallelFetch:137 4 threads are active. 12044 items left to be fetched
>2013-12-12 03:20:30,961 7277:140452703483648: grinder.ParallelFetch:INFO: ParallelFetch:137 4 threads are active. 12044 items left to be fetched
>2013-12-12 03:20:30,968 7277:140452692993792: grinder.ParallelFetch:INFO: ParallelFetch:137 4 threads are active. 12041 items left to be fetched
># ....
>2013-12-12 03:21:32,822 7277:140452724463360: grinder.ParallelFetch:INFO: ParallelFetch:308 WorkerThread deleting ActiveObject
>2013-12-12 03:21:32,826 7277:140452724463360: grinder.ParallelFetch:INFO: ParallelFetch:323 Thread ending
>2013-12-12 03:21:32,833 7277:140452692993792: grinder.ParallelFetch:INFO: ParallelFetch:137 3 threads are active. 3 items left to be fetched
>2013-12-12 03:21:32,834 7277:140452692993792: grinder.ParallelFetch:INFO: ParallelFetch:308 WorkerThread deleting ActiveObject
>2013-12-12 03:21:32,838 7277:140452692993792: grinder.ParallelFetch:INFO: ParallelFetch:323 Thread ending
>2013-12-12 03:21:32,840 7277:140452713973504: grinder.ParallelFetch:INFO: ParallelFetch:137 2 threads are active. 2 items left to be fetched
>2013-12-12 03:21:32,841 7277:140452713973504: grinder.ParallelFetch:INFO: ParallelFetch:308 WorkerThread deleting ActiveObject
>2013-12-12 03:21:32,845 7277:140452713973504: grinder.ParallelFetch:INFO: ParallelFetch:323 Thread ending
>2013-12-12 03:21:32,847 7277:140452703483648: grinder.ParallelFetch:INFO: ParallelFetch:137 1 threads are active. 1 items left to be fetched
>2013-12-12 03:21:32,847 7277:140452703483648: grinder.ParallelFetch:INFO: ParallelFetch:308 WorkerThread deleting ActiveObject
>2013-12-12 03:21:32,851 7277:140452703483648: grinder.ParallelFetch:INFO: ParallelFetch:323 Thread ending
>2013-12-12 03:21:33,264 7277:140452734953216: grinder.ParallelFetch:INFO: ParallelFetch:218 All threads have finished.
>2013-12-12 03:21:33,354 7277:140452734953216: grinder.ParallelFetch:INFO: ParallelFetch:237 ParallelFetch: 12047 items successfully processed, 0 downloaded, 0 items had errors
>2013-12-12 03:21:33,355 7277:140452734953216: grinder.ParallelFetch:INFO: ParallelFetch:242 Transferred [19337218024] bytes of [rpm]
>2013-12-12 03:21:33,355 7277:140452734953216: grinder.ParallelFetch:INFO: ParallelFetch:243 Transferred [19337218024] total bytes in 128.943819046 seconds
>2013-12-12 03:21:33,355 7277:140452734953216: grinder.RepoFetch:INFO: RepoFetch:202 Finalizing metadata, moving /var/lib/pulp//repos/content/dist/rhel/rhui/server/6/6Server/x86_64/os//repodata.new to /var/lib/pulp//repos/content/dist/rhel/rhui/server/6/6Server/x86_64/os//repodata
>2013-12-12 03:21:33,674 7277:140452734953216: grinder.RepoFetch:INFO: RepoFetch:156 Cleaning any orphaned packages..
>2013-12-12 03:21:47,503 7277:140452734953216: grinder.RepoFetch:INFO: RepoFetch:161 Processed <>,<https://cdn.redhat.com//content/dist/rhel/rhui/server/6/6Server/x86_64/os> with <12047> items in [143] seconds. Report: 12047 successes, 0 downloads, 0 errors
>2013-12-12 03:21:47,505 7277:140452734953216: grinder.ParallelFetch:INFO: ParallelFetch:187 Grinder stopping
>2013-12-12 03:21:47,506 7277:140452734953216: grinder.ParallelFetch:INFO: ParallelFetch:271 stop() invoked
>2013-12-12 03:21:47,506 7277:140452734953216: grinder.ParallelFetch:INFO: ParallelFetch:281 stop() completed
>2013-12-12 03:21:47,507 7277:140452734953216: grinder.ParallelFetch:INFO: ParallelFetch:191 Told thread <<WorkerThread(Thread-6, stopped daemon 140452724463360)>> to stop
>2013-12-12 03:21:47,508 7277:140452734953216: grinder.ParallelFetch:INFO: ParallelFetch:271 stop() invoked
>2013-12-12 03:21:47,508 7277:140452734953216: grinder.ParallelFetch:INFO: ParallelFetch:281 stop() completed
>2013-12-12 03:21:47,509 7277:140452734953216: grinder.ParallelFetch:INFO: ParallelFetch:191 Told thread <<WorkerThread(Thread-7, stopped daemon 140452713973504)>> to stop
>2013-12-12 03:21:47,510 7277:140452734953216: grinder.ParallelFetch:INFO: ParallelFetch:271 stop() invoked
>2013-12-12 03:21:47,510 7277:140452734953216: grinder.ParallelFetch:INFO: ParallelFetch:281 stop() completed
>2013-12-12 03:21:47,512 7277:140452734953216: grinder.ParallelFetch:INFO: ParallelFetch:191 Told thread <<WorkerThread(Thread-8, stopped daemon 140452703483648)>> to stop
>2013-12-12 03:21:47,513 7277:140452734953216: grinder.ParallelFetch:INFO: ParallelFetch:271 stop() invoked
>2013-12-12 03:21:47,513 7277:140452734953216: grinder.ParallelFetch:INFO: ParallelFetch:281 stop() completed
>2013-12-12 03:21:47,514 7277:140452734953216: grinder.ParallelFetch:INFO: ParallelFetch:191 Told thread <<WorkerThread(Thread-9, stopped daemon 140452692993792)>> to stop
>
># mongo task item
>{ "_id" : "8239dbce-18e8-4625-9b45-7681627cf1ca", "scheduled_time" : "2013-12-12T08:19:23Z", "exception" : null, "task_type" : "RepoSyncTask", "job_id" : null, "traceback" : null, "class_name" : null, "_ns" : "task_history", "start_time" : "2013-12-12T03:19:23-05:00", "args" : [ "rhel-6-server-rhui-rpms-6Server-x86_64" ], "task_string" : "Task 1b76a259-6306-11e3-881f-22000afc058d: _sync(rhel-6-server-rhui-rpms-6Server-x86_64, synchronizer=<pulp.server.api.synchronizers.YumSynchronizer object at 0x7fbdeb8dcdd0>, skip={}, max_speed=None, threads=None, progress_callback=<bound method RepoSyncTask.progress_callback of <pulp.server.api.repo_sync_task.RepoSyncTask object at 0x7fbdeb8dc850>>)", "method_name" : "_sync", "finish_time" : "2013-12-12T03:27:41-05:00", "state" : "finished", "result" : true, "kwargs" : { "skip" : { }, "max_speed" : null, "threads" : null }, "progress" : { "status" : "FINISHED", "num_success" : 12047, "size_total" : NumberLong("19337218024"), "num_download" : 0, "item_name" : null, "items_left" : 0, "items_total" : 12047, "item_type" : "", "step" : "Importing data into pulp", "size_left" : 0, "details" : { "rpm" : { "num_success" : 12047, "total_count" : 12047, "items_left" : 0, "size_left" : 0, "total_size_bytes" : NumberLong("19337218024"), "num_error" : 0 } }, "error_details" : [ ], "num_error" : 0 }, "consecutive_failures" : 0, "id" : "1b76a259-6306-11e3-881f-22000afc058d" }
>
># took
>"finish_time" : "2013-12-12T03:27:41-05:00" - "start_time" : "2013-12-12T03:19:23-05:00" = 00:08:18

Actions: View

Attachments on bug 1040739: 835680 | 836325