Bug 795819 - Changeset#promote_content failed with TypeError: can't convert nil into String
Summary: Changeset#promote_content failed with TypeError: can't convert nil into String
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Pulp
Classification: Retired
Component: user-experience
Version: 1.0.0
Hardware: Unspecified
OS: Unspecified
unspecified
high
Target Milestone: ---
: ---
Assignee: Pradeep Kilambi
QA Contact: Preethi Thomas
URL:
Whiteboard:
Depends On: 795816
Blocks:
TreeView+ depends on / blocked
 
Reported: 2012-02-21 15:41 UTC by John Matthews
Modified: 2013-09-09 16:36 UTC (History)
6 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of: 795816
Environment:
Last Closed:
Embargoed:


Attachments (Terms of Use)

Description John Matthews 2012-02-21 15:41:05 UTC
+++ This bug was initially created as a clone of Bug #795816 +++

Description of problem:

Promotion of my RHEL 6 repositories (6.1, 6.2 and 6Server RPMs) failed with a couple of different tracebacks showing up in different logs. The most prominent ones are:

* delayed_jobs.log:  Changeset#promote_content failed with TypeError: can't convert nil into String
* pulp.log:  OSError: [Errno 2] No such file or directory
* production.log:  [ERROR: 2012-02-21 09:41:13 #11959] RestClient::RequestTimeout: Request Timeout

Version-Release number of selected component (if applicable):

* candlepin-0.5.20-1.el6.noarch
* candlepin-tomcat6-0.5.20-1.el6.noarch
* katello-0.1.238-4.el6.noarch
* katello-all-0.1.238-4.el6.noarch
* katello-certs-tools-1.0.2-2.el6.noarch
* katello-cli-0.1.54-2.el6.noarch
* katello-cli-common-0.1.54-2.el6.noarch
* katello-common-0.1.238-4.el6.noarch
* katello-configure-0.1.64-5.el6.noarch
* katello-glue-candlepin-0.1.238-4.el6.noarch
* katello-glue-foreman-0.1.238-4.el6.noarch
* katello-glue-pulp-0.1.238-4.el6.noarch
* katello-httpd-ssl-key-pair-1.0-1.noarch
* katello-qpid-broker-key-pair-1.0-1.noarch
* katello-repos-0.1.5-1.el6.noarch
* katello-selinux-0.1.5-2.el6.noarch
* katello-trusted-ssl-cert-1.0-1.noarch
* pulp-0.0.265-1.el6.noarch
* pulp-admin-0.0.265-1.el6.noarch
* pulp-client-lib-0.0.265-1.el6.noarch
* pulp-common-0.0.265-1.el6.noarch
* pulp-selinux-server-0.0.265-1.el6.noarch

How reproducible:


Steps to Reproduce:
1. Created a Seattle org
2. Added a Library -> Dev1 -> QE1 -> GA1 environment for Seattle
3. Added a Library -> Dev2 environment for Seattle
4. Added a RHEL manifest and selected 3 repositories: RHEL Server 6.1, 6.2, and 6Server, all x86_64
5. Performed sync process manually (takes ~2h)
6. Created new package filter with zsh package and associated it with all RHEL repositories
7. Promoted all of RHEL product Library -> Dev1 (takes a while)
8. Created new package filter with httpd* and associated it with all RHEL repositories
9. Promoted all of RHEL product Library -> Dev2
  
Actual results:

Several tracebacks were displayed and I still don't know if any of them were fatal as the web ui still shows that my changeset is being promoted after over 1 hour later.

Expected results:


Additional info:

katello/production.log:
=======================

[ERROR: 2012-02-21 09:41:13 #11959] RestClient::RequestTimeout: Request Timeout
/usr/lib/ruby/gems/1.8/gems/rest-client-1.6.1/lib/restclient/request.rb:174:in `transmit'
/usr/lib/ruby/gems/1.8/gems/rest-client-1.6.1/lib/restclient/request.rb:60:in `execute'
/usr/lib/ruby/gems/1.8/gems/rest-client-1.6.1/lib/restclient/request.rb:31:in `execute'
/usr/lib/ruby/gems/1.8/gems/rest-client-1.6.1/lib/restclient/resource.rb:54:in `get'
/usr/share/katello/lib/resources/candlepin.rb:36:in `get'
/usr/share/katello/app/controllers/api/candlepin_proxies_controller.rb:20:in `get'
/usr/lib/ruby/gems/1.8/gems/actionpack-3.0.10/lib/action_controller/metal/implicit_render.rb:4:in `send_action'
/usr/lib/ruby/gems/1.8/gems/actionpack-3.0.10/lib/action_controller/metal/implicit_render.rb:4:in `send_action'
/usr/lib/ruby/gems/1.8/gems/actionpack-3.0.10/lib/abstract_controller/base.rb:150:in `process_action'
/usr/lib/ruby/gems/1.8/gems/actionpack-3.0.10/lib/action_controller/metal/rendering.rb:11:in `process_action'
/usr/lib/ruby/gems/1.8/gems/actionpack-3.0.10/lib/abstract_controller/callbacks.rb:18:in `process_action'
/usr/lib/ruby/gems/1.8/gems/activesupport-3.0.10/lib/active_support/callbacks.rb:452:in `_run__333878202__process_action__1014791077__callbacks'
/usr/lib/ruby/gems/1.8/gems/activesupport-3.0.10/lib/active_support/callbacks.rb:221:in `_conditional_callback_around_2747'
/usr/share/katello/lib/util/threadsession.rb:79:in `thread_locals'
/usr/lib/ruby/gems/1.8/gems/activesupport-3.0.10/lib/active_support/callbacks.rb:220:in `_conditional_callback_around_2747'
/usr/lib/ruby/gems/1.8/gems/activesupport-3.0.10/lib/active_support/callbacks.rb:441:in `_run__333878202__process_action__1014791077__callbacks'
/usr/lib/ruby/gems/1.8/gems/activesupport-3.0.10/lib/active_support/callbacks.rb:410:in `send'
/usr/lib/ruby/gems/1.8/gems/activesupport-3.0.10/lib/active_support/callbacks.rb:410:in `_run_process_action_callbacks'
/usr/lib/ruby/gems/1.8/gems/activesupport-3.0.10/lib/active_support/callbacks.rb:94:in `send'
/usr/lib/ruby/gems/1.8/gems/activesupport-3.0.10/lib/active_support/callbacks.rb:94:in `run_callbacks'
/usr/lib/ruby/gems/1.8/gems/actionpack-3.0.10/lib/abstract_controller/callbacks.rb:17:in `process_action'
/usr/lib/ruby/gems/1.8/gems/actionpack-3.0.10/lib/action_controller/metal/rescue.rb:17:in `process_action'
/usr/lib/ruby/gems/1.8/gems/actionpack-3.0.10/lib/action_controller/metal/instrumentation.rb:30:in `process_action'
/usr/lib/ruby/gems/1.8/gems/activesupport-3.0.10/lib/active_support/notifications.rb:52:in `instrument'
/usr/lib/ruby/gems/1.8/gems/activesupport-3.0.10/lib/active_support/notifications/instrumenter.rb:21:in `instrument'
/usr/lib/ruby/gems/1.8/gems/activesupport-3.0.10/lib/active_support/notifications.rb:52:in `instrument'
/usr/lib/ruby/gems/1.8/gems/actionpack-3.0.10/lib/action_controller/metal/instrumentation.rb:29:in `process_action'
/usr/lib/ruby/gems/1.8/gems/actionpack-3.0.10/lib/abstract_controller/base.rb:119:in `process'
/usr/lib/ruby/gems/1.8/gems/actionpack-3.0.10/lib/abstract_controller/rendering.rb:41:in `process'
/usr/lib/ruby/gems/1.8/gems/actionpack-3.0.10/lib/action_controller/metal.rb:138:in `dispatch'
/usr/lib/ruby/gems/1.8/gems/actionpack-3.0.10/lib/action_controller/metal/rack_delegation.rb:14:in `dispatch'
/usr/lib/ruby/gems/1.8/gems/actionpack-3.0.10/lib/action_controller/metal.rb:178:in `action'
/usr/lib/ruby/gems/1.8/gems/actionpack-3.0.10/lib/action_dispatch/routing/route_set.rb:62:in `call'
/usr/lib/ruby/gems/1.8/gems/actionpack-3.0.10/lib/action_dispatch/routing/route_set.rb:62:in `dispatch'
/usr/lib/ruby/gems/1.8/gems/actionpack-3.0.10/lib/action_dispatch/routing/route_set.rb:27:in `call'
/usr/lib/ruby/gems/1.8/gems/rack-mount-0.7.1/lib/rack/mount/route_set.rb:150:in `call'
/usr/lib/ruby/gems/1.8/gems/rack-mount-0.7.1/lib/rack/mount/code_generation.rb:93:in `recognize'
/usr/lib/ruby/gems/1.8/gems/rack-mount-0.7.1/lib/rack/mount/code_generation.rb:110:in `optimized_each'
/usr/lib/ruby/gems/1.8/gems/rack-mount-0.7.1/lib/rack/mount/code_generation.rb:92:in `recognize'
/usr/lib/ruby/gems/1.8/gems/rack-mount-0.7.1/lib/rack/mount/route_set.rb:141:in `call'
/usr/lib/ruby/gems/1.8/gems/actionpack-3.0.10/lib/action_dispatch/routing/route_set.rb:493:in `call'
/usr/lib/ruby/gems/1.8/gems/warden-1.0.5/lib/warden/manager.rb:35:in `call'
/usr/lib/ruby/gems/1.8/gems/warden-1.0.5/lib/warden/manager.rb:34:in `catch'
/usr/lib/ruby/gems/1.8/gems/warden-1.0.5/lib/warden/manager.rb:34:in `call'
/usr/lib/ruby/gems/1.8/gems/sass-3.1.4/lib/sass/../sass/plugin/rack.rb:54:in `call'
/usr/lib/ruby/gems/1.8/gems/actionpack-3.0.10/lib/action_dispatch/middleware/best_standards_support.rb:17:in `call'
/usr/lib/ruby/gems/1.8/gems/actionpack-3.0.10/lib/action_dispatch/middleware/head.rb:14:in `call'
/usr/lib/ruby/gems/1.8/gems/rack-1.3.0/lib/rack/methodoverride.rb:24:in `call'
/usr/lib/ruby/gems/1.8/gems/actionpack-3.0.10/lib/action_dispatch/middleware/params_parser.rb:21:in `call'
/usr/lib/ruby/gems/1.8/gems/actionpack-3.0.10/lib/action_dispatch/middleware/flash.rb:182:in `call'
/usr/lib/ruby/gems/1.8/gems/actionpack-3.0.10/lib/action_dispatch/middleware/session/abstract_store.rb:149:in `call'
/usr/lib/ruby/gems/1.8/gems/actionpack-3.0.10/lib/action_dispatch/middleware/cookies.rb:302:in `call'
/usr/lib/ruby/gems/1.8/gems/activerecord-3.0.10/lib/active_record/query_cache.rb:32:in `call'
/usr/lib/ruby/gems/1.8/gems/activerecord-3.0.10/lib/active_record/connection_adapters/abstract/query_cache.rb:28:in `cache'
/usr/lib/ruby/gems/1.8/gems/activerecord-3.0.10/lib/active_record/query_cache.rb:12:in `cache'
/usr/lib/ruby/gems/1.8/gems/activerecord-3.0.10/lib/active_record/query_cache.rb:31:in `call'
/usr/lib/ruby/gems/1.8/gems/activerecord-3.0.10/lib/active_record/connection_adapters/abstract/connection_pool.rb:354:in `call'
/usr/lib/ruby/gems/1.8/gems/actionpack-3.0.10/lib/action_dispatch/middleware/callbacks.rb:46:in `call'
/usr/lib/ruby/gems/1.8/gems/activesupport-3.0.10/lib/active_support/callbacks.rb:416:in `_run_call_callbacks'
/usr/lib/ruby/gems/1.8/gems/actionpack-3.0.10/lib/action_dispatch/middleware/callbacks.rb:44:in `call'
/usr/lib/ruby/gems/1.8/gems/rack-1.3.0/lib/rack/sendfile.rb:102:in `call'
/usr/lib/ruby/gems/1.8/gems/actionpack-3.0.10/lib/action_dispatch/middleware/remote_ip.rb:48:in `call'
/usr/lib/ruby/gems/1.8/gems/actionpack-3.0.10/lib/action_dispatch/middleware/show_exceptions.rb:47:in `call'
/usr/lib/ruby/gems/1.8/gems/railties-3.0.10/lib/rails/rack/logger.rb:13:in `call'
/usr/lib/ruby/gems/1.8/gems/rack-1.3.0/lib/rack/runtime.rb:17:in `call'
/usr/lib/ruby/gems/1.8/gems/rack-1.3.0/lib/rack/lock.rb:34:in `call'
/usr/lib/ruby/gems/1.8/gems/railties-3.0.10/lib/rails/application.rb:168:in `call'
/usr/lib/ruby/gems/1.8/gems/railties-3.0.10/lib/rails/application.rb:77:in `send'
/usr/lib/ruby/gems/1.8/gems/railties-3.0.10/lib/rails/application.rb:77:in `method_missing'
/usr/lib/ruby/gems/1.8/gems/rack-1.3.0/lib/rack/urlmap.rb:52:in `call'
/usr/lib/ruby/gems/1.8/gems/rack-1.3.0/lib/rack/urlmap.rb:46:in `each'
/usr/lib/ruby/gems/1.8/gems/rack-1.3.0/lib/rack/urlmap.rb:46:in `call'
/usr/lib/ruby/gems/1.8/gems/thin-1.2.11/lib/thin/connection.rb:84:in `pre_process'
/usr/lib/ruby/gems/1.8/gems/thin-1.2.11/lib/thin/connection.rb:82:in `catch'
/usr/lib/ruby/gems/1.8/gems/thin-1.2.11/lib/thin/connection.rb:82:in `pre_process'
/usr/lib/ruby/gems/1.8/gems/thin-1.2.11/lib/thin/connection.rb:57:in `process'
/usr/lib/ruby/gems/1.8/gems/thin-1.2.11/lib/thin/connection.rb:42:in `receive_data'
/usr/lib/ruby/gems/1.8/gems/eventmachine-0.12.10/lib/eventmachine.rb:256:in `run_machine'
/usr/lib/ruby/gems/1.8/gems/eventmachine-0.12.10/lib/eventmachine.rb:256:in `run'
/usr/lib/ruby/gems/1.8/gems/thin-1.2.11/lib/thin/backends/base.rb:61:in `start'
/usr/lib/ruby/gems/1.8/gems/thin-1.2.11/lib/thin/server.rb:159:in `start'
/usr/lib/ruby/gems/1.8/gems/thin-1.2.11/lib/thin/controllers/controller.rb:86:in `start'
/usr/lib/ruby/gems/1.8/gems/thin-1.2.11/lib/thin/runner.rb:185:in `send'
/usr/lib/ruby/gems/1.8/gems/thin-1.2.11/lib/thin/runner.rb:185:in `run_command'
/usr/lib/ruby/gems/1.8/gems/thin-1.2.11/lib/thin/runner.rb:151:in `run!'
/usr/lib/ruby/gems/1.8/gems/thin-1.2.11/bin/thin:6
/usr/share/katello/script/thin:24:in `load'
/usr/share/katello/script/thin:24

katello/delayed_jobs.log:
=========================

2012-02-21T09:36:35-0500: [Worker(delayed_job host:qetello01.usersys.redhat.com pid:11790)] Changeset#promote_content failed with TypeError: can't convert nil into String - 0 failed attempts
2012-02-21T09:36:36-0500: [Worker(delayed_job host:qetello01.usersys.redhat.com pid:11790)] PERMANENTLY removing Changeset#promote_content because of 1 consecutive failures.
can't convert nil into String
/usr/lib/ruby/gems/1.8/gems/json-1.4.6/lib/json/common.rb:146:in `initialize'
/usr/lib/ruby/gems/1.8/gems/json-1.4.6/lib/json/common.rb:146:in `new'
/usr/lib/ruby/gems/1.8/gems/json-1.4.6/lib/json/common.rb:146:in `parse'
/usr/lib/ruby/gems/1.8/gems/multi_json-1.0.3/lib/multi_json/engines/json_gem.rb:13:in `decode'
/usr/lib/ruby/gems/1.8/gems/multi_json-1.0.3/lib/multi_json.rb:65:in `decode'
/usr/lib/ruby/gems/1.8/gems/tire-0.3.12/lib/tire/index.rb:60:in `store'
/usr/lib/ruby/gems/1.8/gems/tire-0.3.12/lib/tire/model/search.rb:134:in `update_index'
/usr/lib/ruby/gems/1.8/gems/activesupport-3.0.10/lib/active_support/callbacks.rb:414:in `_run_update_elasticsearch_index_callbacks'
/usr/lib/ruby/gems/1.8/gems/tire-0.3.12/lib/tire/model/search.rb:130:in `send'
/usr/lib/ruby/gems/1.8/gems/tire-0.3.12/lib/tire/model/search.rb:130:in `update_index'
/usr/lib/ruby/gems/1.8/gems/tire-0.3.12/lib/tire/model/callbacks.rb:21:in `_callback_after_73'
/usr/lib/ruby/gems/1.8/gems/activesupport-3.0.10/lib/active_support/callbacks.rb:441:in `_run_save_callbacks'
/usr/lib/ruby/gems/1.8/gems/activerecord-3.0.10/lib/active_record/callbacks.rb:273:in `create_or_update'
/usr/lib/ruby/gems/1.8/gems/activerecord-3.0.10/lib/active_record/persistence.rb:60:in `save!'
/usr/lib/ruby/gems/1.8/gems/activerecord-3.0.10/lib/active_record/validations.rb:49:in `save!'
/usr/lib/ruby/gems/1.8/gems/activerecord-3.0.10/lib/active_record/attribute_methods/dirty.rb:30:in `save!'
/usr/lib/ruby/gems/1.8/gems/activerecord-3.0.10/lib/active_record/transactions.rb:245:in `save!'
/usr/lib/ruby/gems/1.8/gems/activerecord-3.0.10/lib/active_record/transactions.rb:292:in `with_transaction_returning_status'
/usr/lib/ruby/gems/1.8/gems/activerecord-3.0.10/lib/active_record/connection_adapters/abstract/database_statements.rb:139:in `transaction'
/usr/lib/ruby/gems/1.8/gems/activerecord-3.0.10/lib/active_record/transactions.rb:207:in `transaction'
/usr/lib/ruby/gems/1.8/gems/activerecord-3.0.10/lib/active_record/transactions.rb:290:in `with_transaction_returning_status'
/usr/lib/ruby/gems/1.8/gems/activerecord-3.0.10/lib/active_record/transactions.rb:245:in `save!'
/usr/share/katello/app/models/changeset.rb:304:in `promote_content'
/usr/share/katello/app/models/async_operation.rb:41:in `send'
/usr/share/katello/app/models/async_operation.rb:41:in `perform'
/usr/lib/ruby/gems/1.8/gems/delayed_job-2.1.4/lib/delayed/backend/base.rb:87:in `invoke_job'
/usr/lib/ruby/gems/1.8/gems/delayed_job-2.1.4/lib/delayed/worker.rb:120:in `run'
/usr/lib/ruby/1.8/timeout.rb:67:in `timeout'
/usr/lib/ruby/gems/1.8/gems/delayed_job-2.1.4/lib/delayed/worker.rb:120:in `run'
/usr/lib/ruby/1.8/benchmark.rb:308:in `realtime'
/usr/lib/ruby/gems/1.8/gems/delayed_job-2.1.4/lib/delayed/worker.rb:119:in `run'
/usr/lib/ruby/gems/1.8/gems/delayed_job-2.1.4/lib/delayed/worker.rb:177:in `reserve_and_run_one_job'
/usr/lib/ruby/gems/1.8/gems/delayed_job-2.1.4/lib/delayed/worker.rb:104:in `work_off'
/usr/lib/ruby/gems/1.8/gems/delayed_job-2.1.4/lib/delayed/worker.rb:103:in `times'
/usr/lib/ruby/gems/1.8/gems/delayed_job-2.1.4/lib/delayed/worker.rb:103:in `work_off'
/usr/lib/ruby/gems/1.8/gems/delayed_job-2.1.4/lib/delayed/worker.rb:78:in `start'
/usr/lib/ruby/1.8/benchmark.rb:308:in `realtime'
/usr/lib/ruby/gems/1.8/gems/delayed_job-2.1.4/lib/delayed/worker.rb:77:in `start'
/usr/lib/ruby/gems/1.8/gems/delayed_job-2.1.4/lib/delayed/worker.rb:74:in `loop'
/usr/lib/ruby/gems/1.8/gems/delayed_job-2.1.4/lib/delayed/worker.rb:74:in `start'
/usr/lib/ruby/gems/1.8/gems/delayed_job-2.1.4/lib/delayed/command.rb:104:in `run'
/usr/lib/ruby/gems/1.8/gems/delayed_job-2.1.4/lib/delayed/command.rb:83:in `run_process'
/usr/lib/ruby/gems/1.8/gems/daemons-1.1.4/lib/daemons/application.rb:249:in `call'
/usr/lib/ruby/gems/1.8/gems/daemons-1.1.4/lib/daemons/application.rb:249:in `start_proc'
/usr/lib/ruby/gems/1.8/gems/daemons-1.1.4/lib/daemons/daemonize.rb:197:in `call'
/usr/lib/ruby/gems/1.8/gems/daemons-1.1.4/lib/daemons/daemonize.rb:197:in `call_as_daemon'
/usr/lib/ruby/gems/1.8/gems/daemons-1.1.4/lib/daemons/application.rb:253:in `start_proc'
/usr/lib/ruby/gems/1.8/gems/daemons-1.1.4/lib/daemons/application.rb:293:in `start'
/usr/lib/ruby/gems/1.8/gems/daemons-1.1.4/lib/daemons/controller.rb:70:in `run'
/usr/lib/ruby/gems/1.8/gems/daemons-1.1.4/lib/daemons.rb:195:in `run_proc'
/usr/lib/ruby/gems/1.8/gems/daemons-1.1.4/lib/daemons/cmdline.rb:109:in `call'
/usr/lib/ruby/gems/1.8/gems/daemons-1.1.4/lib/daemons/cmdline.rb:109:in `catch_exceptions'
/usr/lib/ruby/gems/1.8/gems/daemons-1.1.4/lib/daemons.rb:194:in `run_proc'
/usr/lib/ruby/gems/1.8/gems/delayed_job-2.1.4/lib/delayed/command.rb:81:in `run_process'
/usr/lib/ruby/gems/1.8/gems/delayed_job-2.1.4/lib/delayed/command.rb:75:in `daemonize'
/usr/lib/ruby/gems/1.8/gems/delayed_job-2.1.4/lib/delayed/command.rb:73:in `times'
/usr/lib/ruby/gems/1.8/gems/delayed_job-2.1.4/lib/delayed/command.rb:73:in `daemonize'
script/delayed_job:5
2012-02-21T09:36:43-0500: [Worker(delayed_job host:qetello01.usersys.redhat.com pid:11790)] 1 jobs processed at 0.0008 j/s, 1 failed ...

pulp/pulp.log:
==============
2012-02-21 09:42:20,373 11359:140499912484608: pulp.server.tasking.task:ERROR: task:474 Task failed: Task 88ffa4ca-5c96-11e1-8b39-52540053a678: _clone(Seattle-Dev2-Red_Hat_Enterprise_Linux_Server-Red_Hat_Enterprise_Linux_6_Server_RPMs_x86_64_6_2, feed=parent, progress_callback=<bound method RepoCloneTask.progress_callback of <pulp.server.api.repo_clone_task.RepoCloneTask object at 0x7fc8b801b690>>, clone_name=Red Hat Enterprise Linux 6 Server RPMs x86_64 6.2, relative_path=Seattle/Dev2/content/dist/rhel/server/6/6.2/x86_64/os, synchronizer=<pulp.server.api.synchronizers.YumSynchronizer object at 0x7fc8b801be90>, filters=['rhel6_zsh', 'rhel6_httpd'], id=Seattle-Red_Hat_Enterprise_Linux_Server-Red_Hat_Enterprise_Linux_6_Server_RPMs_x86_64_6_2, groupid=['product:69', 'env:6', 'org:2', 'content:168'])
Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/pulp/server/tasking/task.py", line 420, in run
    result = self.callable(*self.args, **self.kwargs)
  File "/usr/lib/python2.6/site-packages/pulp/server/api/repo_sync.py", line 137, in _clone
    _sync(clone_id, progress_callback=progress_callback, synchronizer=synchronizer)
  File "/usr/lib/python2.6/site-packages/pulp/server/api/repo_sync.py", line 272, in _sync
    progress_callback, synchronizer, max_speed, threads)
  File "/usr/lib/python2.6/site-packages/pulp/server/api/repo_sync.py", line 355, in fetch_content
    progress_callback, max_speed, threads)
  File "/usr/lib/python2.6/site-packages/pulp/server/api/synchronizers.py", line 163, in sync
    max_speed=max_speed, threads=threads)
  File "/usr/lib/python2.6/site-packages/pulp/server/api/synchronizers.py", line 1241, in local
    blacklist_packages, progress_callback)
  File "/usr/lib/python2.6/site-packages/pulp/server/api/synchronizers.py", line 977, in _sync_rpms
    item_size = self._calculate_bytes(src_repo_dir, [pkg.relativepath])
  File "/usr/lib/python2.6/site-packages/pulp/server/api/synchronizers.py", line 673, in _calculate_bytes
    bytes += os.stat(os.path.join(dir, pkg))[6]
OSError: [Errno 2] No such file or directory: '/var/lib/pulp//repos/Seattle/Library/content/dist/rhel/server/6/6.2/x86_64/os/Packages/binutils-devel-2.20.51.0.2-5.11.el6.i686.rpm'

Comment 1 Pradeep Kilambi 2012-02-23 21:07:36 UTC
commit 33006d7e09b5093c64d31ee37554dfbcdbfd19c3

Test:
* sync el6 repo from cdn (make sure repodata has href with a dir eg: Package/foo.rpm). regular repos dont show this as an issue

* clone the el6 repo on pulp

* now resync the cloned el6 repo

* watch the logs to make sure you dont see any "No such file or directory" error

* make sure the packages after resync are still under Packages/ dir in repodir and not under os dir

Comment 2 Jeff Ortel 2012-02-23 22:49:14 UTC
build: 1.0.0-2

Comment 3 Ivan Necas 2012-02-24 10:58:49 UTC
I can confirm this error, but I'm not sure it's related directly to the description of the original bug. When reproducing this one, I've seen the packages not being positioned correctly, but I haven't seen  the 'No such file or directory' error. Also on the machine with the original bug, there were no packages in incorrect place.

The original bug appears in packages synchronized from remote repo.The strange thing is that for some packages synchronized from remote repo the link is not created. However it seems the package should be there (when cloning, it shouts that the package is missing). So at the end, most (but not all) links are created.

Comment 4 Ivan Necas 2012-02-24 11:01:31 UTC
Another observation:

Pulp says:

 2012-02-21 17:58:16,785 11788:140544395171584: pulp.server.api.synchronizers:INFO       : synchronizers:783 YumSynchronizer reported 5632 successes, 4729 downloads, 1 er       rors

But in grinder there are only 4729 lines with line like:

grinder.log:2012-02-21 17:55:35,435 11788:140544374191872: grinder.BaseFetch:INFO: activeobject:160 Create a link in repo directory for the package at /var/lib/pulp//repos/Seattle/Library/content/dist/rhel/server/6/6.1/x86_64/os//Packages/zlib-1.2.3-25.el6.i686.rpm to ../../../../../../../../../../../../packages/zlib/1.2.3/25.el6/i686/36a/zlib-1.2.3-25.el6.i686.rpm

So it seems like the link was not created for packages, that were already downloaded for another repo (e.g. 6.2)

Comment 5 Ivan Necas 2012-02-24 11:12:58 UTC
Althought there are also lines in grinder.log like:

grinder.log:2012-02-21 17:54:09,017 11788:140544374191872: grinder.BaseFetch:INFO: activeobject:160 Symlink missing in repo directory. Creating link /var/lib/pulp//repos/Seattle/Library/content/dist/rhel/server/6/6.1/x86_64/os//Packages/xulrunner-1.9.2.20-2.el6_1.x86_64.rpm to ../../../../../../../../../../../../packages/xulrunner/1.9.2.20/2.el6_1/x86_64/dd4/xulrunner-1.9.2.20-2.el6_1.x86_64.rpm

There are only 177 for the repo. So we still missing links for over 700 packages

Comment 6 Ivan Necas 2012-02-24 11:24:22 UTC
I suspect this lines starting grinder/BaseFetch.py:193 to cause this troubles:

        # Acquire a write lock so no other process duplicates the effort
        grinder_write_locker = GrinderLock(filePath + '.lock')
        existing_lock_pid = grinder_write_locker.readlock()
        new_pid = os.getpid()
        if existing_lock_pid and int(existing_lock_pid) != new_pid and grinder_write_locker.isvalid(existing_lock_pid):
            # If there is an existing write pid
            # and if the pid is not same as the current pid
            # and pid is valid there is another process alive
            # and handling this, exit here.
            LOG.debug("another process is already handling this path [%s] and is alive; no need to process this again " % filePath)
            return (BaseFetch.STATUS_NOOP,None)

Bare in mind that synchronization of 6.1 and 6.2 repos runs concurrently, there might be situations, that the package is being downloaded for another repo. In this case it's skipped and the symlink is no longer created.

Comment 7 Pradeep Kilambi 2012-02-24 13:42:30 UTC
Ivan could you open a separate bug for remote sync issue you are mentioning against pulp. The issue i fixed and discussed with Og was related to promotions and syncing promoted repos. 

The issue you're mentioning seems possible if two concurrent repo syncs are running with same package being downloaded. Lets leave this current issue for promotions and track the remote sync issue as a separate bug.

Comment 8 Preethi Thomas 2012-02-24 14:15:12 UTC
as per prad's comment above

verifying the original issue

found no errors in log on clone or re syncing the

[root@preethi-el6-pulp ~]# rpm -q pulp
pulp-1.0.0-2.el6.noarch


[root@preethi-el6-pulp ~]# 
[root@preethi-el6-pulp ~]# pulp-admin -u admin -p admin repo create --id rhel6_2 --feed https://cdn.redhat.com/content/dist/rhel/rhui/server/6/6.2/x86_64/os/ --feed_ca CDN/cdn.redhat.com-chain.crt --feed_cert CDN/rhcontent.pem
Successfully created repository [ rhel6_2 ]

[root@preethi-el6-pulp ~]# pulp-admin -u admin -p admin repo sync --id rhel6_2 -F
Sync for repository rhel6_2 started
Sync: Finished
6880/6880 new items downloaded
0/6880 existing items processed

Item Details: 
Tree Files: 6/6
RPMs: 6874/6874


[root@preethi-el6-pulp ~]# 
[root@preethi-el6-pulp ~]# pulp-admin -u admin -p admin repo clone --id rhel6_2  --clone_id=rhe6_2_clone-origin --feed=origin -F
Repository [rhel6_2] is being cloned as [rhe6_2_clone-origin]
Clone: Finished
Item Details: 
Tree Files: 6/6
RPMs: 6874/6874

[root@preethi-el6-pulp ~]# pulp-admin -u admin -p admin repo sync --id=rhe6_2_clone-origin  -F
Sync for repository rhe6_2_clone-origin started
Sync: Finished
0/6880 new items downloaded
6880/6880 existing items processed

Item Details: 
Tree Files: 6/6
RPMs: 6874/6874



[root@preethi-el6-pulp ~]# pulp-admin -u admin -p admin repo clone --id rhel6_2  --clone_id=rhe6_2_clone-parent --feed=parent -F
Repository [rhel6_2] is being cloned as [rhe6_2_clone-parent]
Clone: Finished
Item Details: 
Tree Files: 6/6
RPMs: 6874/6874

[root@preethi-el6-pulp ~]# 
[root@preethi-el6-pulp ~]# Write failed: Broken pipe
[pthomas@pthomas-lt ~]$ ssh root.redhat.com
root.redhat.com's password: 
Permission denied, please try again.
root.redhat.com's password: 
Last login: Thu Feb 23 17:20:20 2012 from vpn-11-3.rdu.redhat.com
[root@preethi-el6-pulp ~]# pulp-admin -u admin -p admin repo sync --id=rhe6_2_clone-parent  -F
Sync for repository rhe6_2_clone-parent started
Sync: Finished
3525/6880 new items downloaded
3355/6880 existing items processed

Item Details: 
Tree Files: 6/6
RPMs: 6874/6874


[root@preethi-el6-pulp ~]# ls -l /var/lib/pulp/
total 112
drwxr-xr-x.    3 apache apache  4096 Feb 23 17:19 cache
drwxr-xr-x.    3 apache apache  4096 Feb 23 17:19 distributions
-rw-r--r--.    1 root   root       0 Feb 23 17:13 init.flag
drwxr-xr-x. 2842 apache apache 90112 Feb 23 19:11 packages
drwxr-xr-x.    6 apache apache  4096 Feb 23 17:10 plugins
drwxr-xr-x.    5 apache apache  4096 Feb 23 20:20 published
drwxr-xr-x.    5 apache apache  4096 Feb 23 22:50 repos
[root@preethi-el6-pulp ~]# ls -l /var/lib/pulp/repos/
total 12
drwxr-xr-x. 3 apache apache 4096 Feb 23 17:17 content
drwxrwxr-x. 6 apache apache 4096 Feb 23 21:17 rhe6_2_clone-origin
drwxrwxr-x. 6 apache apache 4096 Feb 24 07:30 rhe6_2_clone-parent
[root@preethi-el6-pulp ~]# ls -l /var/lib/pulp/repos/rhe6_2_clone-origin/
total 4604
drwxr-xr-x. 2 apache apache    4096 Feb 23 20:19 drpms
drwxr-xr-x. 3 apache apache    4096 Feb 23 20:19 images
drwxr-xr-x. 2 apache apache  643072 Feb 23 20:19 Packages
drwxr-xr-x. 2 apache apache    4096 Feb 23 21:17 repodata
lrwxrwxrwx. 1 apache apache      74 Feb 23 20:19 treeinfo -> ../../distributions/ks-Red Hat Enterprise Linux-Server-6.2-x86_64/treeinfo
-rw-r--r--. 1 apache apache 4047964 Feb 23 21:17 updateinfo.xml
[root@preethi-el6-pulp ~]# ls -l /var/lib/pulp/repos/rhe6_2_clone-parent/
total 4604
drwxr-xr-x. 2 apache apache    4096 Feb 23 22:51 drpms
drwxr-xr-x. 3 apache apache    4096 Feb 23 22:51 images
drwxr-xr-x. 2 apache apache  643072 Feb 23 22:51 Packages
drwxr-xr-x. 2 apache apache    4096 Feb 24 07:30 repodata
lrwxrwxrwx. 1 apache apache      74 Feb 23 22:51 treeinfo -> ../../distributions/ks-Red Hat Enterprise Linux-Server-6.2-x86_64/treeinfo
-rw-r--r--. 1 apache apache 4047964 Feb 24 07:30 updateinfo.xml
[root@preethi-el6-pulp ~]#

Comment 9 Og Maciel 2012-02-24 19:50:43 UTC
Cannot test it until pulp-1.0.0-2 lands with SE

Comment 10 Preethi Thomas 2012-02-24 20:16:42 UTC
Pulp v1.0 is released
Closed Current Release.

Comment 11 Preethi Thomas 2012-02-24 20:17:59 UTC
Pulp v1.0 is released.


Note You need to log in before you can comment on or make changes to this bug.