Pulp

I'm setting up a reproducer against the 2.7.0 release on EL7.

I did a Pulp 2.7.0 installation w/ Qpid on a yum updated EL7.1 installation. I was not able to reproduce the issue. Here are my pulp packages:

pulp-admin-client-2.7.0-0.8.rc.el7.noarch
pulp-server-2.7.0-0.8.rc.el7.noarch
pulp-rpm-plugins-2.7.0-0.8.rc.el7.noarch
pulp-puppet-admin-extensions-2.7.0-0.8.rc.el7.noarch
pulp-rpm-yumplugins-2.7.0-0.8.rc.el7.noarch
python-pulp-common-2.7.0-0.8.rc.el7.noarch
python-pulp-client-lib-2.7.0-0.8.rc.el7.noarch
pulp-consumer-client-2.7.0-0.8.rc.el7.noarch
pulp-puppet-plugins-2.7.0-0.8.rc.el7.noarch
pulp-rpm-admin-extensions-2.7.0-0.8.rc.el7.noarch
pulp-agent-2.7.0-0.8.rc.el7.noarch
python-pulp-puppet-common-2.7.0-0.8.rc.el7.noarch
python-kombu-3.0.24-10.pulp.el7.noarch
python-pulp-repoauth-2.7.0-0.8.rc.el7.noarch
python-pulp-bindings-2.7.0-0.8.rc.el7.noarch
pulp-puppet-handlers-2.7.0-0.8.rc.el7.noarch
pulp-rpm-consumer-extensions-2.7.0-0.8.rc.el7.noarch
pulp-selinux-2.7.0-0.8.rc.el7.noarch
python-pulp-agent-lib-2.7.0-0.8.rc.el7.noarch
python-pulp-oid_validation-2.7.0-0.8.rc.el7.noarch
pulp-puppet-consumer-extensions-2.7.0-0.8.rc.el7.noarch
pulp-rpm-handlers-2.7.0-0.8.rc.el7.noarch
python-isodate-0.5.0-4.pulp.el7.noarch
python-pulp-rpm-common-2.7.0-0.8.rc.el7.noarch

Using mongo cli, I captured the following contents of the 'workers' collection. That collection holds the heartbeats that the resource manager believes are "old" records. If a worker hasn't checked in within 5 minutes its considered missing and its work is cancelled, which is what seems to be happening here.

Here is what the workers collection looks like on my system that could not reproduce the issue:

[cloud-user@bmbouter-1380-reproducer yum.repos.d]$ mongo
MongoDB shell version: 2.6.11
connecting to: test
Welcome to the MongoDB shell.
For interactive help, type "help".
For more comprehensive documentation, see
        http://docs.mongodb.org/
Questions? Try the support group
        http://groups.google.com/group/mongodb-user
Server has startup warnings: 
2015-11-18T17:00:30.789-0500 [initandlisten] 
2015-11-18T17:00:30.789-0500 [initandlisten] ** WARNING: Readahead for /var/lib/mongodb is set to 4096KB
2015-11-18T17:00:30.789-0500 [initandlisten] **          We suggest setting it to 256KB (512 sectors) or less
2015-11-18T17:00:30.789-0500 [initandlisten] **          http://dochub.mongodb.org/core/readahead
> use pulp_database
switched to db pulp_database
> db.workers.find().pretty()
{
        "_id" : "scheduler@bmbouter-1380-reproducer.example.com",
        "last_heartbeat" : ISODate("2015-11-18T22:08:34.368Z")
}
{
        "_id" : "reserved_resource_worker-2@bmbouter-1380-reproducer.example.com",
        "last_heartbeat" : ISODate("2015-11-18T23:09:16.665Z")
}
{
        "_id" : "reserved_resource_worker-3@bmbouter-1380-reproducer.example.com",
        "last_heartbeat" : ISODate("2015-11-18T23:09:16.664Z")
}
{
        "_id" : "reserved_resource_worker-0@bmbouter-1380-reproducer.example.com",
        "last_heartbeat" : ISODate("2015-11-18T23:09:16.664Z")
}
{
        "_id" : "reserved_resource_worker-1@bmbouter-1380-reproducer.example.com",
        "last_heartbeat" : ISODate("2015-11-18T23:08:53.192Z")
}
{
        "_id" : "resource_manager@bmbouter-1380-reproducer.example.com",
        "last_heartbeat" : ISODate("2015-11-18T23:09:04.383Z")
}

Can someone who is experiencing the bug connect to their mongodb and paste their contents of the 'workers' table to this ticket?
Also someone who is experiencing the bug talk some about their timezone configs. Perhaps this is a timezone related issue?
Is someone out there using 2.7.0 and not experiencing this issue (besides myself)?

I started experiencing this after trying to run updates over the weekend.
There was a dependency issue related to libqpid-proton.so.2.

CentOS 6.7 - no timezone changes

DB output:

db.workers.find().pretty()
{
        "_id" : "scheduler@reposrv",
        "last_heartbeat" : ISODate("2015-11-18T22:33:02.586Z")
}
{
        "_id" : "reserved_resource_worker-0@reposrv",
        "last_heartbeat" : ISODate("2015-11-18T17:33:16.554Z")
}
{
        "_id" : "reserved_resource_worker-1@reposrv",
        "last_heartbeat" : ISODate("2015-11-18T17:33:16.555Z")
}
{
        "_id" : "reserved_resource_worker-2@reposrv",
        "last_heartbeat" : ISODate("2015-11-18T17:33:16.555Z")
}
{
        "_id" : "reserved_resource_worker-3@reposrv",
        "last_heartbeat" : ISODate("2015-11-18T17:33:16.559Z")
}

Dependency issue:

Resolving Dependencies
--> Running transaction check
---> Package qpid-proton-c.x86_64 0:0.9-3.el6 will be updated
--> Processing Dependency: libqpid-proton.so.2()(64bit) for package: qpid-cpp-server-0.26-9.el6.x86_64
--> Processing Dependency: libqpid-proton.so.2()(64bit) for package: qpid-cpp-client-0.26-9.el6.x86_64
---> Package qpid-proton-c.x86_64 0:0.10-2.el6 will be an update
--> Finished Dependency Resolution
Error: Package: qpid-cpp-client-0.26-9.el6.x86_64 (@pulp-2-stable)
           Requires: libqpid-proton.so.2()(64bit)
           Removing: qpid-proton-c-0.9-3.el6.x86_64 (@epel)
               libqpid-proton.so.2()(64bit)
           Updated By: qpid-proton-c-0.10-2.el6.x86_64 (epel-6)
               Not found
Error: Package: qpid-cpp-server-0.26-9.el6.x86_64 (@pulp-2-stable)
           Requires: libqpid-proton.so.2()(64bit)
           Removing: qpid-proton-c-0.9-3.el6.x86_64 (@epel)
               libqpid-proton.so.2()(64bit)
           Updated By: qpid-proton-c-0.10-2.el6.x86_64 (epel-6)
               Not found

Installed packages:

grep pulp:

python-pulp-client-lib-2.7.0-1.el6.noarch
python-pulp-oid_validation-2.7.0-1.el6.noarch
pulp-nodes-consumer-extensions-2.7.0-1.el6.noarch
pulp-puppet-admin-extensions-2.7.0-1.el6.noarch
python-pulp-docker-common-1.0.2-1.el6.noarch
python-pulp-python-common-1.0.1-1.el6.noarch
python-rhsm-1.8.0-2.pulp.el6.x86_64
pulp-docker-plugins-1.0.2-1.el6.noarch
python-pulp-bindings-2.7.0-1.el6.noarch
python-pulp-puppet-common-2.7.0-1.el6.noarch
python-pulp-repoauth-2.7.0-1.el6.noarch
pulp-nodes-common-2.7.0-1.el6.noarch
pulp-rpm-plugins-2.7.0-1.el6.noarch
pulp-rpm-admin-extensions-2.7.0-1.el6.noarch
pulp-rpm-handlers-2.7.0-1.el6.noarch
python-kombu-3.0.24-10.pulp.el6.noarch
pulp-docker-admin-extensions-1.0.2-1.el6.noarch
mod_wsgi-3.4-2.pulp.el6.x86_64
pulp-python-admin-extensions-1.0.1-1.el6.noarch
python-pulp-common-2.7.0-1.el6.noarch
python-pulp-agent-lib-2.7.0-1.el6.noarch
pulp-admin-client-2.7.0-1.el6.noarch
pulp-server-2.7.0-1.el6.noarch
pulp-puppet-plugins-2.7.0-1.el6.noarch
pulp-puppet-tools-2.7.0-1.el6.noarch
pulp-rpm-consumer-extensions-2.7.0-1.el6.noarch
pulp-selinux-2.7.0-1.el6.noarch
python-isodate-0.5.0-4.pulp.el6.noarch
python-pulp-rpm-common-2.7.0-1.el6.noarch
pulp-consumer-client-2.7.0-1.el6.noarch
pulp-nodes-admin-extensions-2.7.0-1.el6.noarch
pulp-agent-2.7.0-1.el6.noarch
pulp-puppet-handlers-2.7.0-1.el6.noarch
pulp-puppet-consumer-extensions-2.7.0-1.el6.noarch
pulp-rpm-yumplugins-2.7.0-1.el6.noarch
pulp-python-plugins-1.0.1-1.el6.noarch

grep qpid:

python-gofer-qpid-2.6.6-2.el6.noarch
qpid-cpp-client-0.26-9.el6.x86_64
python-qpid-common-0.26-3.el6.noarch
python-qpid-qmf-0.26-2.el6.x86_64
qpid-cpp-server-store-0.26-9.el6.x86_64
python-qpid-0.26-3.el6.noarch
qpid-qmf-0.26-2.el6.x86_64
qpid-proton-c-0.9-3.el6.x86_64
qpid-cpp-server-0.26-9.el6.x86_64

@chandlermelton Regarding the dependency issue, that is filed under #1340. For this issue, I think I can why it's happening.

Your output and mine were taken close to each in actual time (< 1 hour) I believe, yet my timestamps show times like

ISODate("2015-11-18T23:09:16.664Z")

versus yours like:

ISODate("2015-11-18T17:33:16.554Z")

Note, that the scheduler gets its timestamps from inside Pulp code so that one looks right. Make sure to compare the resource_manager and reserved_resource_worker entries.

The code that checks for missing workers is likely getting it wrong because of the non-UTC format. It looks like the timestamp from your system is wrong because (IIRC), that wasn't the UTC when you captured your output and yet the timestamp format shows indicates it is UTC because it is in Zulu time (the 'Z' at the end).

Can you run this python snippet an paste back the output?

from datetime import datetime, timedelta
oldest_heartbeat = datetime.utcnow() - timedelta(seconds=300)
oldest_heartbeat.isoformat()

Also can you repaste your db.workers.find().pretty() once more around the same moment you capture the output from the snippet above?

Is everyone experiencing this issue running CentOS?

The root cause it would seem is that celery (which provides the heartbeats) is not reporting it in UTC format when it is sent over.

I strongly suspect this is affecting CentOS 2.7.0 users, but not RHEL or Fedora users. I couldn't reproduce on RHEL and I've run the 2.7.0 beta code in the past on Fedora without issue. Other users (including our QA) have run it on both as well without this issue.

Also, I just spoke with another developer who verbally reported he was using CentOS briefly with a 2.7.0 alpha/beta and he noted that he had some strange worker's going missing problems at the same time.

What celery version do you have installed on CentOS w/ Pulp 2.7.0?

python: '2015-11-19T00:46:29.429320'

mongo:
{
"_id" : "scheduler@reposrv",
"last_heartbeat" : ISODate("2015-11-19T00:48:03.615Z")
}
{
"_id" : "reserved_resource_worker-0@reposrv",
"last_heartbeat" : ISODate("2015-11-18T19:48:20.951Z")
}
{
"_id" : "reserved_resource_worker-3@reposrv",
"last_heartbeat" : ISODate("2015-11-18T19:48:20.954Z")
}
{
"_id" : "reserved_resource_worker-1@reposrv",
"last_heartbeat" : ISODate("2015-11-18T19:48:20.945Z")
}
{
"_id" : "reserved_resource_worker-2@reposrv",
"last_heartbeat" : ISODate("2015-11-18T19:48:20.947Z")
}
{
"_id" : "resource_manager@reposrv",
"last_heartbeat" : ISODate("2015-11-18T19:48:00.515Z")
}

python-celery-3.1.11-1.el6.noarch

I saw in the email thread (after posting) that discussion was moved here. What appears to be the requested info based on thread and above:

- RHEL 6.7 x86_64 with all updates applied except for the qpid issue mentioned above
- qpid-cpp-server 0.26-9.el6.x86_64
- python-celery-3.1.11-1.el6.noarch
- All packages are installed from the pulp-2 stable repo as well.

db.workers.find().pretty()

{
"_id" : "scheduler@f.q.d.n",
"last_heartbeat" : ISODate("2015-11-19T12:44:00.543Z")
}
{
"_id" : "reserved_resource_worker-1@f.q.d.n",
"last_heartbeat" : ISODate("2015-11-19T07:45:05.162Z")
}
{
"_id" : "reserved_resource_worker-0@f.q.d.n",
"last_heartbeat" : ISODate("2015-11-19T07:45:05.156Z")
}
{
"_id" : "resource_manager@f.q.d.n",
"last_heartbeat" : ISODate("2015-11-19T07:44:51.458Z")

For completeness, I'm running Pulp 2.7.0 on CentOS 6.6 using rabbmitmq 3.5.3. (Though I'm 95% sure this issue existed when I was using qpid and upgraded to 2.7, which I wrote off as being part of the broken dependencies per #1340, so with that in mind I switched to rabbit.)

$ mongo
MongoDB shell version: 2.4.14
connecting to: test
>  use pulp_database
switched to db pulp_database

> db.workers.find().pretty()
{
        "_id" : "scheduler@pulp-btp-01",
        "last_heartbeat" : ISODate("2015-11-19T13:40:00.331Z")
}
{
        "_id" : "reserved_resource_worker-0@pulp-btp-01",
        "last_heartbeat" : ISODate("2015-11-19T09:40:22.604Z")
}
{
        "_id" : "reserved_resource_worker-2@pulp-btp-01",
        "last_heartbeat" : ISODate("2015-11-19T09:40:22.607Z")
}
{
        "_id" : "reserved_resource_worker-3@pulp-btp-01",
        "last_heartbeat" : ISODate("2015-11-19T09:40:22.610Z")
}
{
        "_id" : "reserved_resource_worker-1@pulp-btp-01",
        "last_heartbeat" : ISODate("2015-11-19T09:40:22.609Z")
}
{
        "_id" : "resource_manager@pulp-btp-01",
        "last_heartbeat" : ISODate("2015-11-19T09:40:17.371Z")
}

$ rpm -qa | grep pulp
python-pulp-client-lib-2.7.0-1.el6.noarch
pulp-rpm-plugins-2.7.0-1.el6.noarch
pulp-rpm-yumplugins-2.7.0-1.el6.noarch
mod_wsgi-3.4-2.pulp.el6.x86_64
python-pulp-rpm-common-2.7.0-1.el6.noarch
pulp-nodes-consumer-extensions-2.7.0-1.el6.noarch
pulp-agent-2.7.0-1.el6.noarch
pulp-python-admin-extensions-1.0.1-1.el6.noarch
pulp-admin-client-2.7.0-1.el6.noarch
pulp-server-2.7.0-1.el6.noarch
pulp-puppet-admin-extensions-2.7.0-1.el6.noarch
python-pulp-common-2.7.0-1.el6.noarch
python-pulp-agent-lib-2.7.0-1.el6.noarch
python-pulp-repoauth-2.7.0-1.el6.noarch
pulp-nodes-common-2.7.0-1.el6.noarch
pulp-puppet-plugins-2.7.0-1.el6.noarch
pulp-puppet-consumer-extensions-2.7.0-1.el6.noarch
pulp-rpm-handlers-2.7.0-1.el6.noarch
python-pulp-python-common-1.0.1-1.el6.noarch
python-pulp-bindings-2.7.0-1.el6.noarch
python-pulp-oid_validation-2.7.0-1.el6.noarch
pulp-nodes-admin-extensions-2.7.0-1.el6.noarch
pulp-rpm-consumer-extensions-2.7.0-1.el6.noarch
pulp-selinux-2.7.0-1.el6.noarch
pulp-python-plugins-1.0.1-1.el6.noarch
m2crypto-0.21.1.pulp-8.el6.x86_64
pulp-consumer-client-2.7.0-1.el6.noarch
pulp-rpm-admin-extensions-2.7.0-1.el6.noarch
python-isodate-0.5.0-4.pulp.el6.noarch
python-rhsm-1.8.0-2.pulp.el6.x86_64
python-pulp-puppet-common-2.7.0-1.el6.noarch
pulp-nodes-parent-2.7.0-1.el6.noarch
pulp-puppet-handlers-2.7.0-1.el6.noarch
python-kombu-3.0.24-10.pulp.el6.noarch
zzjason@pulp-btp-01:~> rpm -qa | grep celery
python-celery-3.1.11-1.el6.noarch

jluza I applied the patch to my instance and wanted to give feedback.

# apply patch
cd /usr/lib/python2.6/site-packages/pulp/server/
sudo wget https://pulp.plan.io/attachments/download/176/0001-droping-workers-test-fix.patch
sudo patch -p3 < 0001-droping-workers-test-fix.patch

# restart services
sudo service pulp_workers restart
sudo service pulp_resource_manager restart
sudo service pulp_celerybeat restart
sudo service goferd restart

and the "Worker x has gone missing" errors no longer show up, but instead show every 60 seconds the following:

Nov 19 10:24:03 pulp-btp-01 pulp: pulp.server.async.scheduler:ERROR: worker.last:2015-11-19 15:24:01.586000 worker.name:reserved_resource_worker-0@pulp-btp-01 oldest:2015-11-19 15:19:03.227505
Nov 19 10:24:03 pulp-btp-01 pulp: pulp.server.async.scheduler:ERROR: worker.last:2015-11-19 15:24:02.683000 worker.name:reserved_resource_worker-1@pulp-btp-01 oldest:2015-11-19 15:19:03.227505
Nov 19 10:24:03 pulp-btp-01 pulp: pulp.server.async.scheduler:ERROR: worker.last:2015-11-19 15:24:01.583000 worker.name:reserved_resource_worker-2@pulp-btp-01 oldest:2015-11-19 15:19:03.227505
Nov 19 10:24:03 pulp-btp-01 pulp: pulp.server.async.scheduler:ERROR: worker.last:2015-11-19 15:24:02.679000 worker.name:reserved_resource_worker-3@pulp-btp-01 oldest:2015-11-19 15:19:03.227505
Nov 19 10:24:03 pulp-btp-01 pulp: pulp.server.async.scheduler:ERROR: worker.last:2015-11-19 15:23:57.874000 worker.name:resource_manager@pulp-btp-01 oldest:2015-11-19 15:19:03.227505

Tasks remain stuck in the queue in a Waiting state.

Yeah, that one is my debugging message, I included it into patch, to show the differences between times. To remove it, just remove _logger.error line from scheduler.py.

You mentioned the patch as a workaround, but it doesn't appear to fix the issue for me. Or are you still testing/working on a true fix?

ashbyj@imsweb.com wrote:

and the "Worker x has gone missing" errors no longer show up, but instead show every 60 seconds the following:

From above I understood, it solved the dropping workers issue. Are you still experiencing the dropping problem?

I'm not member of pulp team, however I believe, true fix lies in chose of right version of messaging related packages. As I wrote earlier, I tested (big thanks to ipanova) pulp-2.7 on f20 didn't have have this issue.

Today I tried to install gofer-2.7.0-1.git.66.8a1ecd6.fc20 but it didn't help

Yes, I believe I am still experiencing the issues on CentOS 6 pulp 2.7. After applying the patch, I still get errors every 60 seconds. The only difference is that it is no longer hitting the "if worker.last_heartbeat < oldest_heartbeat_time" condition here:

# /usr/lib/python2.6/site-packages/pulp/server/async/scheduler.py
    def check_celery_processes(self):
...
        for worker in worker_list:
            _logger.error("worker.last:%s worker.name:%s oldest:%s" % (worker.last_heartbeat, worker.name, oldest_heartbeat_time))
            if worker.last_heartbeat < oldest_heartbeat_time:
                msg = _("Worker '%s' has gone missing, removing from list of workers") % worker.name
                _logger.error(msg)
                _delete_worker(worker.name)
...

Tasks get stuck in a waiting state as I assume they are never able to be served.

Anything you would like me to test on my end?

cause of the error message is this line:

_logger.error("worker.last:%s worker.name:%s oldest:%s" % (worker.last_heartbeat, worker.name, oldest_heartbeat_time))

I have very bad habit to use error logs as my debug logs (because it's easier to search them)

Can you remove the line mention above from your pulp code and restart the pulp services? Then if you could check /var/log/messages and search for errors. Also if you can start your tasks and then connect to your mongo db and paste output for db.workers.find() and db.reserved_resources.find()

No prob, we've all got bad habits :). I removed the _logger.error line and restarted pulp services and /var/log/messages looks clean now.

Here is the output you asked for.

$ date
Fri Nov 20 09:33:52 EST 2015
$ mongo
MongoDB shell version: 2.4.14
connecting to: test
> use pulp_database
switched to db pulp_database
> db.workers.find().pretty()
{
        "_id" : "scheduler@pulp-btp-01",
        "last_heartbeat" : ISODate("2015-11-20T19:33:21Z")
}
{
        "_id" : "reserved_resource_worker-0@pulp-btp-01",
        "last_heartbeat" : ISODate("2015-11-20T14:33:56.464Z")
}
{
        "_id" : "reserved_resource_worker-1@pulp-btp-01",
        "last_heartbeat" : ISODate("2015-11-20T14:33:57.506Z")
}
{
        "_id" : "reserved_resource_worker-2@pulp-btp-01",
        "last_heartbeat" : ISODate("2015-11-20T14:33:56.517Z")
}
{
        "_id" : "reserved_resource_worker-3@pulp-btp-01",
        "last_heartbeat" : ISODate("2015-11-20T14:33:57.620Z")
}
{
        "_id" : "resource_manager@pulp-btp-01",
        "last_heartbeat" : ISODate("2015-11-20T14:33:52.011Z")
}
> db.reserved_resources.find()
>

db.reserved_resources.find() did not return anything as you can see.

From user reports, users running 2.7.0 on EL6 or CentOS6 will experience this problem, but users on EL7, CentOS7, or the fedoras will not.

I'm setting up an EL6 reproducer now. I'll investigate why the heartbeat times in a different format there. It's likely a packaging different. One thing I'm not clear on yet is why now with 2.7.0 and not with 2.6.x?

I've reproduced the problem on EL6 with rabbitMQ. Every 60 seconds I receive the logs:

Nov 20 14:02:58 bmbouter-1380-reproducer-el6 pulp: pulp.server.async.scheduler:ERROR: Worker 'reserved_resource_worker-0@bmbouter-1380-reproducer-el6' has gone 
missing, removing from list of workers
Nov 20 14:02:58 bmbouter-1380-reproducer-el6 pulp: pulp.server.async.tasks:ERROR: The worker named reserved_resource_worker-0@bmbouter-1380-reproducer-el6 is mi
ssing. Canceling the tasks in its queue.
Nov 20 14:02:58 bmbouter-1380-reproducer-el6 pulp: pulp.server.async.scheduler:ERROR: Worker 'reserved_resource_worker-1@bmbouter-1380-reproducer-el6' has gone 
missing, removing from list of workers
Nov 20 14:02:58 bmbouter-1380-reproducer-el6 pulp: pulp.server.async.tasks:ERROR: The worker named reserved_resource_worker-1@bmbouter-1380-reproducer-el6 is mi
ssing. Canceling the tasks in its queue.
Nov 20 14:02:58 bmbouter-1380-reproducer-el6 pulp: pulp.server.async.scheduler:ERROR: Worker 'reserved_resource_worker-2@bmbouter-1380-reproducer-el6' has gone 
missing, removing from list of workers
Nov 20 14:02:58 bmbouter-1380-reproducer-el6 pulp: pulp.server.async.tasks:ERROR: The worker named reserved_resource_worker-2@bmbouter-1380-reproducer-el6 is mi
ssing. Canceling the tasks in its queue.
Nov 20 14:02:58 bmbouter-1380-reproducer-el6 pulp: pulp.server.async.scheduler:ERROR: Worker 'reserved_resource_worker-3@bmbouter-1380-reproducer-el6' has gone 
missing, removing from list of workers
Nov 20 14:02:58 bmbouter-1380-reproducer-el6 pulp: pulp.server.async.tasks:ERROR: The worker named reserved_resource_worker-3@bmbouter-1380-reproducer-el6 is mi
ssing. Canceling the tasks in its queue.
Nov 20 14:02:58 bmbouter-1380-reproducer-el6 pulp: pulp.server.async.scheduler:ERROR: Worker 'resource_manager@bmbouter-1380-reproducer-el6' has gone missing, r
emoving from list of workers
Nov 20 14:02:58 bmbouter-1380-reproducer-el6 pulp: pulp.server.async.tasks:ERROR: The worker named resource_manager@bmbouter-1380-reproducer-el6 is missing. Canceling the tasks in its queue.
Nov 20 14:02:58 bmbouter-1380-reproducer-el6 pulp: pulp.server.async.scheduler:ERROR: There are 0 pulp_resource_manager processes running. Pulp will not operate correctly without at least one pulp_resource_mananger process running.
Nov 20 14:03:18 bmbouter-1380-reproducer-el6 pulp: pulp.server.async.worker_watcher:INFO: New worker 'reserved_resource_worker-0@bmbouter-1380-reproducer-el6' discovered
Nov 20 14:03:19 bmbouter-1380-reproducer-el6 pulp: pulp.server.async.worker_watcher:INFO: New worker 'reserved_resource_worker-1@bmbouter-1380-reproducer-el6' discovered
Nov 20 14:03:21 bmbouter-1380-reproducer-el6 pulp: pulp.server.async.worker_watcher:INFO: New worker 'reserved_resource_worker-2@bmbouter-1380-reproducer-el6' discovered
Nov 20 14:03:22 bmbouter-1380-reproducer-el6 pulp: pulp.server.async.worker_watcher:INFO: New worker 'reserved_resource_worker-3@bmbouter-1380-reproducer-el6' discovered
Nov 20 14:03:26 bmbouter-1380-reproducer-el6 pulp: pulp.server.async.worker_watcher:INFO: New worker 'resource_manager@bmbouter-1380-reproducer-el6' discovered

Indeed my timestamps look like yours:

{
        "_id" : "scheduler@bmbouter-1380-reproducer-el6",
        "last_heartbeat" : ISODate("2015-11-20T19:05:29.056Z")
}
{
        "_id" : "reserved_resource_worker-0@bmbouter-1380-reproducer-el6",
        "last_heartbeat" : ISODate("2015-11-20T15:06:48.217Z")
}
{
        "_id" : "reserved_resource_worker-1@bmbouter-1380-reproducer-el6",
        "last_heartbeat" : ISODate("2015-11-20T15:06:49.811Z")
}
{
        "_id" : "reserved_resource_worker-2@bmbouter-1380-reproducer-el6",
        "last_heartbeat" : ISODate("2015-11-20T15:06:51.633Z")
}
{
        "_id" : "reserved_resource_worker-3@bmbouter-1380-reproducer-el6",
        "last_heartbeat" : ISODate("2015-11-20T15:06:52.955Z")
}
{
        "_id" : "resource_manager@bmbouter-1380-reproducer-el6",
        "last_heartbeat" : ISODate("2015-11-20T15:06:26.780Z")
}

Now to investigate why...

In the meantime, is there anything I can do to "force" a task to complete? I've got some servers I need to provision and registering/binding to the pulp server is a necessary step. Also, let me know if there is anything I can troubleshoot or investigate to help.

I have an experimental fix for this. It's not a good idea to modify files installed with RPM, so be sure you can back out your change properly if you choose to try this. It would be good if someone could confirm that it resolves the issue. I've tested it, but it needs tests written and to be included in a build. In the meantime, if you know how to apply the following safely here is the diff:

[bmbouter@localhost pulp]$ git diff
diff --git a/server/pulp/server/async/scheduler.py b/server/pulp/server/async/scheduler.py
index ac4bfe6..fc048cd 100644
--- a/server/pulp/server/async/scheduler.py
+++ b/server/pulp/server/async/scheduler.py
@@ -235,7 +235,7 @@ class Scheduler(beat.Scheduler):

         # this is not an event that gets sent anywhere. We process it
         # immediately.
-        scheduler_event = {'timestamp': time.time(),
+        scheduler_event = {'local_received': time.time(),
                            'type': 'scheduler-event',
                            'hostname': ("%s@%s" % (SCHEDULER_WORKER_NAME, platform.node()))}
         worker_watcher.handle_worker_heartbeat(scheduler_event)
diff --git a/server/pulp/server/async/worker_watcher.py b/server/pulp/server/async/worker_watcher.py
index 5052442..4ab3b6e 100644
--- a/server/pulp/server/async/worker_watcher.py
+++ b/server/pulp/server/async/worker_watcher.py
@@ -41,7 +41,7 @@ def _parse_and_log_event(event):
              (ie: 'worker-heartbeat'), and 'worker_name' is the name of the worker as a string.
     :rtype: dict
     """
-    event_info = {'timestamp': datetime.utcfromtimestamp(event['timestamp']),
+    event_info = {'timestamp': datetime.utcfromtimestamp(event['local_received']),
                   'type': event['type'],
                   'worker_name': event['hostname']}

I can confirm that I was blocked by that issue when I upgraded my Centos6-based pulp from 2.6 to 2.7.

However, by applying bmbouter's patch to my local installation, the issue was solved and I was able to schedule tasks using pulp-admin.

I can confirm (RHEL 6.7 x86_64, Pulp 2.7 from pulp-2 stable repo, qpid-cpp-server 0.26-9.el6.x86_64, python-celery-3.1.11-1.el6.noarch) that this fixes both the issue of the disappearing workers and the inability to schedule and run tasks.

Looks good from where I'm sitting. Thank you!

After applying the patch, I'm having trouble getting the pulp_celerybeat service to stay running.

# /var/log/messages
Dec  2 10:32:45 pulp-btp-01 pulp: celery.beat:INFO: beat: Starting...
Dec  2 10:32:45 pulp-btp-01 pulp: pulp.server.db.connection:INFO: Attempting to connect to localhost:27017
Dec  2 10:32:45 pulp-btp-01 pulp: pulp.server.async.scheduler:INFO: Worker Timeout Monitor Started
Dec  2 10:32:45 pulp-btp-01 pulp: pulp.server.db.connection:INFO: Write concern for Mongo connection: {'w': 1}
Dec  2 10:32:45 pulp-btp-01 pulp: pulp.server.async.scheduler:INFO: Event Monitor Starting
Dec  2 10:23:48 pulp-btp-01 pulp: kombu.mixins:INFO: Connected to amqp://pulp:**@rabbit-btp-dev.example.com:5672//
Dec  2 10:23:48 pulp-btp-01 pulp: celery.beat:CRITICAL: (4209-17216) beat raised exception <type 'exceptions.KeyError'>: KeyError('timestamp',)
Dec  2 10:23:48 pulp-btp-01 pulp: celery.beat:CRITICAL: (4209-17216) Traceback (most recent call last):
Dec  2 10:23:48 pulp-btp-01 pulp: celery.beat:CRITICAL: (4209-17216)   File "/usr/lib/python2.6/site-packages/celery/apps/beat.py", line 112, in start_scheduler
Dec  2 10:23:48 pulp-btp-01 pulp: celery.beat:CRITICAL: (4209-17216)     beat.start()
Dec  2 10:23:48 pulp-btp-01 pulp: celery.beat:CRITICAL: (4209-17216)   File "/usr/lib/python2.6/site-packages/celery/beat.py", line 462, in start
Dec  2 10:23:48 pulp-btp-01 pulp: celery.beat:CRITICAL: (4209-17216)     interval = self.scheduler.tick()
Dec  2 10:23:48 pulp-btp-01 pulp: celery.beat:CRITICAL: (4209-17216)   File "/usr/lib/python2.6/site-packages/pulp/server/async/scheduler.py", line 241, in tick
Dec  2 10:23:48 pulp-btp-01 pulp: celery.beat:CRITICAL: (4209-17216)     worker_watcher.handle_worker_heartbeat(scheduler_event)
Dec  2 10:23:48 pulp-btp-01 pulp: celery.beat:CRITICAL: (4209-17216)   File "/usr/lib/python2.6/site-packages/pulp/server/async/worker_watcher.py", line 84, in handle_worker_heartbeat
Dec  2 10:23:48 pulp-btp-01 pulp: celery.beat:CRITICAL: (4209-17216)     update_one(set__last_heartbeat=datetime.utcfromtimestamp(event.get("local_received", event['timestamp'])), upsert=True)
Dec  2 10:23:48 pulp-btp-01 pulp: celery.beat:CRITICAL: (4209-17216) KeyError: 'timestamp'

and service pulp_celerybeat status then indicates stopped.

Maybe there are some old tasks that need to be flushed out? I'm CentOS 6 w/ rabbitmq.

UPDATE

Scratch that, I needed to revert the original debugging patch from earlier. Pulp celerybeat runs fine and no errors in the logs, however, new tasks are stuck in a Waiting state for me. I don't see anything in the logs. Connections to rabbitmq appear successful all around though. Any ideas?

UPDATE 2

and scratch all other comments. Gofer wasn't running on the consumers since I had shut it down due to this issue. I can confirm that the patch works for me on CentOS 6 w/ rabbitmq. Thanks!!

I got one important detail incorrect - though the timestamp is getting transmitted with the timezone offset, it turns out that the timestamp itself is still getting generated with time.time() which is indeed UTC. The API including the offset with the timestamp is confusing and caused me to think things were different than they were. After further inspection, I was unable to find anywhere that the sender combined its offset with the output of time.time() to set the timestamp and so I believe the timestamp is UTC.

I configured my Vagrant system to use the UTC-5 timezone and I do see the correct UTC time being recorded in my database (which also happens when UTC is my timezone).

I can still think of a few ways that this problem could be happening:

0) The adjust_timestamp() function will cause a problem if the sender and the receiver don't have the same timezone configured. For example, if the sender were in UTC - 5 and the receiver were in UTC - 0, this code will end up subtracting 5 hours from the timestamp and we will think the worker is missing. However, AFAIK nobody has mentioning running their workers on different boxes so this might not be the problem.

1) Late delivery could cause problems. If the beats were stalled for over five minutes and then delivered, the timestamp would show as being five minutes old. This would cause Pulp to think the worker was missing. I doubt this is the cause though.

2) Out of order delivery could cause weirder problems, but I don't believe the broker will do that, especially not this drastically.

I noticed that Brian's comment #21 has something quite odd: there are three different timezones represented in the same comment! Note that the log messages are at 14:02, the scheduler is at 19:05, and the workers are at 15:06. We know that the scheduler's timestamp isn't doing anything weird, so let's assume that it is about 19:00 UTC. Brian's log messages are at about 14:00 which is the UTC-5 timezone that I know that he frequents. But the very strange thing is that the workers are appearing to be at UTC-4, which is 15:00. What is up with that? There is certainly something unusual going on, and I strongly suspect that it is related to the adjust_timestamp() and utcoffset() functions in Celery. I still haven't been able to reproduce this problem in a system of my own so I haven't been able to get in there and see what exactly is happening. Theoretically that code should work as long as the sender and receiver think they are in the same time zone as far as I can understand it.

I found the issue!

https://github.com/celery/celery/issues/1802#issuecomment-161916587

I do think that Celery should fix that line of code (it was a doozy to figure out and a nice facepalm when I did!), and I suggested that they drop trying to deal with translating local time all over the place and just use UTC everywhere (much simpler!).

All of that said, I still think the local_received timestamp will do what we need here, and it gives a little more flexibility for clock drift situations too.

rbarlow: I must say that this is a very nice investigation that you made, quite impressive to be honest !

As for the whole date issue - since I had the bad luck of having to deal with timezones time information in python as my first job and managed to get out of it alive - I think I can say that the only sane way of dealing with time-related information is to use timezone-aware data, which means never using raw timestamps for non-UTC times, but rather another data type such as an ISO8601 (such as the one returned by datetime.datetime.isoformat()) formatted string, and avoid as much as possible conversions between raw timestamps and timezone-aware data.

I've spent this morning investigating whether this bug affects Katello-2.2.0, which ships with Pulp 2.6.0 (and a bunch of patches on top of it). I was surprised to see that the running server did not seem to be experiencing this bug, despite the fact that it uses the same 'timestamp' attribute from the Celery event and the same version of Celery. I spent some time digging around but no matter what I checked I couldn't explain why the system wasn't experiencing this bug.

Then I remembered a note from the Celery bug:

https://github.com/celery/celery/issues/1802#issuecomment-44646818

This was an important detail that I forgot to mention in my previous analysis, because the true reason that that line in the Celery library causes this issue is that the workers import Django and the scheduler does not import Django. Django alters the way that the time and datetime modules work when the USE_TZ setting is True, and Pulp does have that set to True:

https://github.com/pulp/pulp/blob/122e47ec6ad8719156e74795344184e34dc679f4/server/pulp/server/webservices/settings.py#L61

This causes the time offset on the worker to be different than the time offset on the scheduler, which causes the worker watcher to believe the worker has been missing for an hour. I had discovered all of this on Friday morning at late thirty but forgot to mention it in my analysis.

Thus this bug was caused by the coincidental combination of these three things happening at roughly the same time:

0) Many parts of the world switched from daylight savings time to standard time during November,
1) Celery had the bug where it misinterpreted the meaning of that attribute in the Python time library which would only be incorrect for users who have the server's locale set to regions that do observe daylight savings time but are currently in standard time, and
2) Pulp 2.7.0 was released in November around the same time as all of the daylight savings time switches, and is the first Pulp release to use Django.

Though the Celery bug was indeed present in Pulp 2.6, it would only cause problems for Pulp if Django were being used!

Ironically, the Pulp QE process also happened primarily while most of the engineers were in daylight savings time.

Thanks rbarlow!

As a user, what will be the process for me to get this resolved?
Will this be part of a future release I can install with an RPM?

Hello @chandlermelton!

The Pulp team plans to release a 2.7.1 version "very soon" to resolve this issue.

In the meantime, you can work around this issue a few ways:

0) You can change your system's locale to UTC. We can't comment on what effect this will have on other software you are running on your system, but if you are comfortable with using UTC that will solve the issue even without the patch. One could argue that UTC is a great default for servers ☺

1) You can wait until the Pulp team releases a 2.7.1 beta, which will likely only contain the change for this issue. This will likely happen "very soon" (no promises!).

2) You can attempt to manually apply the patch for this issue, which is quite similar though not identical to bmbouter's patch in https://pulp.plan.io/issues/1380#note-23

Just did a scratch build of 2.7.1 beta and verified on EL6 that workers are all reporting very similar times of last heartbeat:

> db.workers.find()
{ "_id" : "reserved_resource_worker-0@rhel6-np-qeos-55562", "last_heartbeat" : ISODate("2015-12-08T04:52:43.981Z") }
{ "_id" : "reserved_resource_worker-1@rhel6-np-qeos-55562", "last_heartbeat" : ISODate("2015-12-08T04:52:44.717Z") }
{ "_id" : "resource_manager@rhel6-np-qeos-55562", "last_heartbeat" : ISODate("2015-12-08T04:52:21.238Z") }
{ "_id" : "scheduler@rhel6-np-qeos-55562", "last_heartbeat" : ISODate("2015-12-08T04:52:16.259Z") }