Bug 1002191

Summary:	nectar timeout error in pulp.log and repo sync stalls/fails after.
Product:	[Retired] Pulp	Reporter:	Preethi Thomas <pthomas>
Component:	z_other	Assignee:	Jason Connor <jconnor>
Status:	CLOSED CURRENTRELEASE	QA Contact:	Preethi Thomas <pthomas>
Severity:	high	Docs Contact:
Priority:	high
Version:	2.2 Beta	CC:	mhrivnak, mmccune, skarmark
Target Milestone:	---	Keywords:	Triaged
Target Release:	2.2.0
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:		Doc Type:	Bug Fix
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2013-09-10 15:45:44 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:

Description Preethi Thomas 2013-08-28 15:18:49 UTC

Description of problem:

There seems like a time out error from nectar in pulp.log

Version-Release number of selected component (if applicable):
[root@ibm-x3650m4-02-vm-03 ~]# rpm -qa pulp-server
pulp-server-2.2.0-0.28.beta.el6.noarch
[root@ibm-x3650m4-02-vm-03 ~]# rpm -qa nectar
[root@ibm-x3650m4-02-vm-03 ~]# rpm -qa |grep nectar
python-nectar-1.1.0-1.el6.noarch


How reproducible:


Steps to Reproduce:
1. [root@ibm-x3650m4-02-vm-03 ~]# pulp-admin rpm repo create --repo-id scientific-linux --feed http://ftp1.scientificlinux.org/linux/scientific/6.4/x86_64/os/
Successfully created repository [scientific-linux]

2. [root@ibm-x3650m4-02-vm-03 ~]#  pulp-admin rpm repo sync run --repo-id scientific-linux

3. Tail -f /var/log/pulp.log


Actual results:

2013-08-28 11:12:48,070 nectar.downloaders.threaded:ERROR: Request timed out.
Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/nectar/downloaders/threaded.py", line 225, in _fetch
    response = session.get(request.url, headers=headers)
  File "/usr/lib/python2.6/site-packages/requests/sessions.py", line 310, in get
    return self.request('GET', url, **kwargs)
  File "/usr/lib/python2.6/site-packages/requests/sessions.py", line 279, in request
    resp = self.send(prep, stream=stream, timeout=timeout, verify=verify, cert=cert, proxies=proxies)
  File "/usr/lib/python2.6/site-packages/requests/sessions.py", line 374, in send
    r = adapter.send(request, **kwargs)
  File "/usr/lib/python2.6/site-packages/requests/adapters.py", line 217, in send
    raise Timeout('Request timed out.')
Timeout: Request timed out.
2013-08-28 11:12:48,072 urllib3.connectionpool:INFO: Starting new HTTP connection (1): ftp1.scientificlinux.org
2013-08-28 11:12:48,074 nectar.downloaders.threaded:ERROR: Request timed out.
Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/nectar/downloaders/threaded.py", line 225, in _fetch
    response = session.get(request.url, headers=headers)
  File "/usr/lib/python2.6/site-packages/requests/sessions.py", line 310, in get
    return self.request('GET', url, **kwargs)
  File "/usr/lib/python2.6/site-packages/requests/sessions.py", line 279, in request
    resp = self.send(prep, stream=stream, timeout=timeout, verify=verify, cert=cert, proxies=proxies)
  File "/usr/lib/python2.6/site-packages/requests/sessions.py", line 374, in send
    r = adapter.send(request, **kwargs)
  File "/usr/lib/python2.6/site-packages/requests/adapters.py", line 217, in send
    raise Timeout('Request timed out.')
Timeout: Request timed out.

Expected results:


Additional info:

Comment 1 Preethi Thomas 2013-08-29 14:27:29 UTC

I am running into this very often. Usually happens on the first sync after the repo created.

Also another issue that I noticed is once this happen, the distribution sync fails.
If you run the sync again, it completes.

[root@hp-dl380pgen8-02-vm-16 ~]# pulp-admin rpm repo sync run --repo-id rhel6-64
+----------------------------------------------------------------------+
                  Synchronizing Repository [rhel6-64]
+----------------------------------------------------------------------+

This command may be exited by pressing ctrl+c without affecting the actual
operation on the server.

Downloading metadata...
[/]
... completed

Downloading repository content...
[==================================================] 100%
RPMs:       4/4 items
Delta RPMs: 0/0 items

... completed

Downloading distribution files...
[==========================================        ] 85%
Distributions: 6/7 items

Errors encountered during distribution sync:

An unexpected error has occurred. More information can be found in the client
log file ~/.pulp/admin.log.

2013-08-29 09:43:13,021 - ERROR - Client-side exception occurred
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/pulp/client/extensions/core.py", line 478, in run
    exit_code = Cli.run(self, args)
  File "/usr/lib/python2.7/site-packages/okaara/cli.py", line 974, in run
    exit_code = command_or_section.execute(self.prompt, remaining_args)
  File "/usr/lib/python2.7/site-packages/pulp/client/extensions/extensions.py", line 224, in execute
    return self.method(*arg_list, **clean_kwargs)
  File "/usr/lib/python2.7/site-packages/pulp/client/commands/repo/sync_publish.py", line 101, in run
    status.display_group_status(self.context, self.renderer, task_group_id)
  File "/usr/lib/python2.7/site-packages/pulp/client/commands/repo/status/status.py", line 63, in display_group_status
    _display_status(context, renderer, task_list)
  File "/usr/lib/python2.7/site-packages/pulp/client/commands/repo/status/status.py", line 95, in _display_status
    _display_task_status(context, renderer, task.task_id, quiet_waiting=quiet_waiting)
  File "/usr/lib/python2.7/site-packages/pulp/client/commands/repo/status/status.py", line 122, in _display_task_status
  renderer.display_report(response.response_body.progress)
  File "/usr/lib/python2.7/site-packages/pulp_rpm/extension/admin/status.py", line 76, in display_report
    self.render_distribution_sync_step(progress_report)
  File "/usr/lib/python2.7/site-packages/pulp_rpm/extension/admin/status.py", line 159, in render_distribution_sync_step
    'message' : error[1]['error_message'],
KeyError: 'error_message'

Comment 2 Michael Hrivnak 2013-09-04 15:09:27 UTC

https://github.com/pulp/nectar/pull/8

Comment 3 Preethi Thomas 2013-09-05 16:59:01 UTC

verified
[root@cloud-qe-9 ~]# rpm -qa pulp-server
pulp-server-2.2.0-0.32.beta.el6.noarch
[root@cloud-qe-9 ~]# rpm -qa python-nectar
python-nectar-1.1.1-1.el6.noarch
[root@cloud-qe-9 ~]# 


[root@ibm-x3650m4-02-vm-03 ~]# pulp-admin rpm consumer package install run -n pulp-test-package --consumer-id rhel5-consumer
This command may be exited via ctrl+c without affecting the request.

[-]
Waiting to begin...
Refresh Repository Metadata             [ OK ]
Downloading Packages                    [ OK ]
Check Package Signatures                [ OK ]
Running Test Transaction                [ OK ]
Running Transaction                     [ OK ]

Install Succeeded

+----------------------------------------------------------------------+
                               Installed
+----------------------------------------------------------------------+

Name:    pulp-test-package
Version: 0.3.1
Arch:    x86_64
Repoid:  pulp-unittest



[root@ibm-x3650m4-02-vm-03 ~]# pulp-admin rpm repo sync run --repo-id rhel5
+----------------------------------------------------------------------+
                    Synchronizing Repository [rhel5]
+----------------------------------------------------------------------+

This command may be exited by pressing ctrl+c without affecting the actual
operation on the server.

Downloading metadata...
[\]
... completed

Downloading repository content...
[==================================================] 100%
RPMs:       0/0 items
Delta RPMs: 0/0 items

... completed

Downloading distribution files...
[==================================================] 100%
Distributions: 18/18 items
... completed

Importing errata...
[\]
... completed

Importing package groups/categories...
[-]
... completed

Publishing packages...
[==================================================] 100%
Packages: 14230/14230 items
... completed

Publishing distributions...
[==================================================] 100%
Distributions: 18/18 items
... completed

Generating metadata
[/]
... completed

Publishing repository over HTTPS
[-]
... completed


[root@ibm-x3650m4-02-vm-03 ~]# pulp-admin repo list
+----------------------------------------------------------------------+
                              Repositories
+----------------------------------------------------------------------+

Id:                  iso-cdn
Display Name:        iso-cdn
Description:         None
Content Unit Counts: 

Id:                  rhel5
Display Name:        rhel5
Description:         None
Content Unit Counts: 
  Distribution:           1
  Erratum:                2519
  Package Category:       6
  Package Group:          99
  Rpm:                    14230
  Yum Repo Metadata File: 1

Id:                  pulp-unittest
Display Name:        pulp-unittest
Description:         None
Content Unit Counts: 
  Distribution:     1
  Erratum:          52
  Package Category: 2
  Package Group:    3
  Rpm:              3


[root@ibm-x3650m4-02-vm-03 ~]# 


[root@hp-dl380pgen8-02-vm-16 ~]# pulp-admin rpm repo sync run --repo-id rhel6-4
+----------------------------------------------------------------------+
                   Synchronizing Repository [rhel6-4]
+----------------------------------------------------------------------+

This command may be exited by pressing ctrl+c without affecting the actual
operation on the server.

Downloading metadata...
[/]
... completed

Downloading repository content...
[==================================================] 100%
RPMs:       0/0 items
Delta RPMs: 0/0 items

... completed

Downloading distribution files...
[==================================================] 100%
Distributions: 7/7 items
... completed

Importing errata...
[\]
... completed

Importing package groups/categories...
[|]
... completed

Publishing packages...
[==================================================] 100%
Packages: 10874/10874 items
... completed

Publishing distributions...
[==================================================] 100%
Distributions: 7/7 items
... completed

Generating metadata
[/]
... completed

Publishing repository over HTTPS
[-]
... completed

[root@hp-dl380pgen8-02-vm-16 ~]# pulp-admin rpm repo list
+----------------------------------------------------------------------+
                            RPM Repositories
+----------------------------------------------------------------------+

Id:                  foo
Display Name:        foo
Description:         None
Content Unit Counts: 
  Erratum:          4
  Package Category: 1
  Package Group:    2
  Rpm:              32

Id:                  pulp_unittest
Display Name:        pulp_unittest
Description:         None
Content Unit Counts: 
  Distribution:     1
  Erratum:          52
  Package Category: 2
  Package Group:    3
  Rpm:              3

Id:                  rhel6-4
Display Name:        rhel6-4
Description:         None
Content Unit Counts: 
  Distribution:           1
  Erratum:                1927
  Package Category:       10
  Package Group:          202
  Rpm:                    10874
  Yum Repo Metadata File: 1


[root@hp-dl380pgen8-02-vm-16 ~]# [root@cloud-qe-9 ~]# pulp-admin rpm repo sync run --repo-id scientific-linux
+----------------------------------------------------------------------+
              Synchronizing Repository [scientific-linux]
+----------------------------------------------------------------------+

This command may be exited by pressing ctrl+c without affecting the actual
operation on the server.

Downloading metadata...
[\]
... completed

Downloading repository content...
[==================================================] 100%
RPMs:       0/0 items
Delta RPMs: 0/0 items

... completed

Downloading distribution files...
[==================================================] 100%
Distributions: 4/4 items
... completed

Importing errata...
[-]
... completed

Importing package groups/categories...
[\]
... completed

Publishing packages...
[==================================================] 100%
Packages: 6449/6449 items
... completed

Publishing distributions...
[==================================================] 100%
Distributions: 4/4 items
... completed

Generating metadata
[|]
... completed

Publishing repository over HTTPS
[-]
... completed


[root@cloud-qe-9 ~]# pulp-admin rpm repo sync run --repo-id centos
+----------------------------------------------------------------------+
                   Synchronizing Repository [centos]
+----------------------------------------------------------------------+

This command may be exited by pressing ctrl+c without affecting the actual
operation on the server.

Downloading metadata...
[-]
... completed

Downloading repository content...
[==================================================] 100%
RPMs:       2/2 items
Delta RPMs: 0/0 items

... completed

Individual package errors encountered during sync:

Package:
http://mirror.rackspace.com/CentOS/6.4/os/x86_64/Packages/mythes-ro-3.3-0.3.test
3.1.el6.noarch.rpm
Error:   


Package:
http://mirror.rackspace.com/CentOS/6.4/os/x86_64/Packages/hyphen-ro-3.3-0.3.test
3.1.el6.noarch.rpm
Error:   



Downloading distribution files...
[==================================================] 100%
Distributions: 4/4 items
... completed

Importing errata...
[-]
... completed

Importing package groups/categories...
[|]
... completed

Publishing packages...
[==================================================] 100%
Packages: 6379/6379 items
... completed

Publishing distributions...
... failed
Generating metadata
[\]
... completed

Publishing repository over HTTPS
[-]
... completed

[root@cloud-qe-9 ~]# pulp-admin repo listr
Usage: pulp-admin [SUB_SECTION, ..] COMMAND
Description: list repositories and manage repo groups

Available Sections:
  group - repository group commands
  tasks - list and cancel tasks related to a specific repository

Available Commands:
  list - lists repositories on the Pulp server
[root@cloud-qe-9 ~]# pulp-admin repo list
+----------------------------------------------------------------------+
                              Repositories
+----------------------------------------------------------------------+

Id:                  iso-repo
Display Name:        iso-repo
Description:         None
Content Unit Counts: 
  Iso: 3

Id:                  scientific-linux
Display Name:        scientific-linux
Description:         None
Content Unit Counts: 
  Distribution:     1
  Package Category: 15
  Package Group:    213
  Rpm:              6449

Id:                  upload
Display Name:        upload
Description:         None
Content Unit Counts: 

Id:                  test1
Display Name:        test1
Description:         None
Content Unit Counts: 
  Erratum:          4
  Package Category: 1
  Package Group:    2
  Rpm:              32

Id:                  bz976561
Display Name:        bz976561
Description:         None
Content Unit Counts: 
  Rpm: 5000

Id:                  rel-url
Display Name:        rel-url
Description:         None
Content Unit Counts: 

Id:                  errata
Display Name:        errata
Description:         None
Content Unit Counts: 

Id:                  zoo
Display Name:        zoo
Description:         None
Content Unit Counts: 
  Erratum:          4
  Package Category: 1
  Package Group:    2
  Rpm:              32

Id:                  pulp_unittest
Display Name:        pulp_unittest
Description:         None
Content Unit Counts: 
  Distribution:     1
  Erratum:          52
  Package Category: 2
  Package Group:    3
  Rpm:              3

Id:                  centos
Display Name:        centos
Description:         None
Content Unit Counts: 
  Distribution:     1
  Package Category: 14
  Package Group:    210
  Rpm:              6379

Comment 4 Preethi Thomas 2013-09-10 15:45:44 UTC

2.2 released
http://repos.fedorapeople.org/repos/pulp/pulp/stable/2.2/