Katello repo sync not working

Arsene · October 9, 2018, 9:52am

Problem:
When setting up a sync plan in foreman it doesn’t sync the repositories. The creation of the sync plan works without errors and it appears in the foreman UI. Doing a manual run of the sync plan works also, it just seems that the schedule doesn’t trigger the syncing.

Expected outcome:
Repositories synced on scheduled date & time.

Foreman and Proxy versions:
foreman-1.19.0-1.el7.noarch
foreman-proxy-1.19.0-1.el7.noarch
pulp-server-2.16.4-1.el7.noarch

Foreman and Proxy plugin versions:

Other relevant data:
[e.g. logs from Foreman and/or the Proxy, modified templates, commands issued, etc]
I don’t see any errors in the logs.

I need some help to debug that issue.
Is the sync task triggered by crond? I’ve not been able to figure out what triggers the syncing.

Thanks for any help.
rgds, Arsene

John_Mitsch · October 16, 2018, 5:09pm

How are you setting up the sync plan? What parameters are you setting?

Arsene · October 17, 2018, 8:47am

My sync-plan looks like:
ID: 7
Name: Daily Sync
Start Date: 2018/10/09 10:00:00
Interval: daily
Enabled: yes
Description: Daily Synchronization Plan
Created at: 2018/10/09 09:53:06
Updated at: 2018/10/09 09:55:58
Products:

ID: 3
Name: Katello
ID: 4
Name: Zabbix
ID: 2
Name: Extra Packages for Enterprise Linux
ID: 5
Name: Bacula
ID: 1
Name: CentOS

I’m able to start the sync-plan manually but it doesn’t start automatically at specified schedule time and I don’t see any error.
Is there a place where I can see if the job is in a scheduler/cron ?

Thanks for any help.

sajha · October 17, 2018, 2:31pm

Do you see a field recurring logic on the sync plan detail page you just created? What is the status of the recurring logic associated to the sync plan?

Arsene · October 17, 2018, 5:35pm

That’s what I see on the UI:
(upload://Af0HcoMPzB7pV65JVVWR6c97nIZ.png) gnome-shell-screenshot-XN88QZ

I don’t see any entries in Monitor → Recurring Logics

sajha · October 17, 2018, 7:02pm

My bad…Didn’t notice the version you were on.

Could you go to one of the products in the sync plan > tasks tab> You should see a task named “Add Sync Plan Products” .
Go to the Dynflow console for that task and see if the child task Actions::Pulp::Repository::UpdateSchedule was invoked and if it succeeded?

Arsene · October 18, 2018, 7:12am

Yes it seems that it did succeed.

Arsene · October 18, 2018, 6:36pm

I could finally find some error in the journal log:

Oct 18 20:28:17 xxxxx.xxxx.xxxx.xxx pulp[10871]: pulp.server.event.http:INFO: [049abcae] (10871-98176) “FINISHED”}, “distribution”: {“items_total”: 0, “state”: “FINISHED”, “error_details”:
Oct 18 20:28:17 xxxxx.xxxx.xxxx.xxx pulp[10871]: pulp.server.event.http:ERROR: [049abcae] (10871-98176) HTTP Notification Failed
Oct 18 20:28:17 xxxxx.xxxx.xxxx.xxx pulp[10871]: pulp.server.event.http:ERROR: [049abcae] (10871-98176) Traceback (most recent call last):
Oct 18 20:28:17 xxxxx.xxxx.xxxx.xxx pulp[10871]: pulp.server.event.http:ERROR: [049abcae] (10871-98176) File “/usr/lib/python2.7/site-packages/pulp/server/event/http.py”, line 57, in send
Oct 18 20:28:17 xxxxx.xxxx.xxxx.xxx pulp[10871]: pulp.server.event.http:ERROR: [049abcae] (10871-98176) headers={‘Content-Type’: ‘application/json’}, timeout=15)
Oct 18 20:28:17 xxxxx.xxxx.xxxx.xxx pulp[10871]: pulp.server.event.http:ERROR: [049abcae] (10871-98176) File “/usr/lib/python2.7/site-packages/requests/api.py”, line 108, in post
Oct 18 20:28:17 xxxxx.xxxx.xxxx.xxx pulp[10871]: pulp.server.event.http:ERROR: [049abcae] (10871-98176) return request(‘post’, url, data=data, json=json, **kwargs)
Oct 18 20:28:17 xxxxx.xxxx.xxxx.xxx pulp[10871]: pulp.server.event.http:ERROR: [049abcae] (10871-98176) File “/usr/lib/python2.7/site-packages/requests/api.py”, line 50, in request
Oct 18 20:28:17xxxxx.xxxx.xxxx.xxx pulp[10871]: pulp.server.event.http:ERROR: [049abcae] (10871-98176) response = session.request(method=method, url=url, **kwargs)
Oct 18 20:28:17xxxxx.xxxx.xxxx.xxx pulp[10871]: pulp.server.event.http:ERROR: [049abcae] (10871-98176) File “/usr/lib/python2.7/site-packages/requests/sessions.py”, line 464, in request
Oct 18 20:28:17 xxxxx.xxxx.xxxx.xxx pulp[10871]: pulp.server.event.http:ERROR: [049abcae] (10871-98176) resp = self.send(prep, **send_kwargs)
Oct 18 20:28:17 xxxxx.xxxx.xxxx.xxx pulp[10871]: pulp.server.event.http:ERROR: [049abcae] (10871-98176) File “/usr/lib/python2.7/site-packages/requests/sessions.py”, line 576, in send
Oct 18 20:28:17 xxxxx.xxxx.xxxx.xxx pulp[10871]: pulp.server.event.http:ERROR: [049abcae] (10871-98176) r = adapter.send(request, **kwargs)
Oct 18 20:28:17 xxxxx.xxxx.xxxx.xxx pulp[10871]: pulp.server.event.http:ERROR: [049abcae] (10871-98176) File “/usr/lib/python2.7/site-packages/requests/adapters.py”, line 424, in send
Oct 18 20:28:17 xxxxx.xxxx.xxxx.xxx pulp[10871]: pulp.server.event.http:ERROR: [049abcae] (10871-98176) raise ConnectionError(e, request=request)
Oct 18 20:28:17 xxxxx.xxxx.xxxx.xxx pulp[10871]: pulp.server.event.http:ERROR: [049abcae] (10871-98176) ConnectionError: HTTPSConnectionPool(host=‘spfy-tfmd01.prd.sapify.ch’, port=443): Max r
Oct 18 20:28:17 xxxxx.xxxx.xxxx.xxx pulp[10881]: pulp.server.async.tasks:INFO: [aafb26e1] resetting consecutive failure count for schedule 5bbc5e83a9431605a30e2eec
Oct 18 20:28:17 xxxxx.xxxx.xxxx.xxx pulp[5466]: celery.worker.strategy:INFO: Received task: pulp.server.async.tasks._queue_reserved_task[b80bd154-250a-4edb-be3f-615942051bcb]

It seems that pulp isn’t able to connect to the foreman server because of an SSL certificate problem, but I’m not able to figure out which certificate it is. I’m using an external certificate for the foreman web interface.
I’ve tried to run foreman-installer again but it didn’t help.

Any Idea where I should investigate further?

sajha · October 18, 2018, 8:27pm

I found these 2 fixes for the problem you are seeing:

https://pulp.plan.io/issues/3780
https://projects.theforeman.org/issues/24083

Once you apply the pulp patch, you can run the rake task update_sync_notifications. That should resolve the issue.

Arsene · October 19, 2018, 9:26am

I did apply the patch of both links and run foreman-rake katello:update_sync_notifications which return an error:
** Invoke katello:update_sync_notifications (first_time)
** Invoke environment (first_time)
** Execute environment
** Execute katello:update_sync_notifications
rake aborted!
RestClient::InternalServerError: 500 Internal Server Error
/opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.1/lib/restclient/abstract_response.rb:223:in exception_with_response' /opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.1/lib/restclient/abstract_response.rb:103:inreturn!’
/opt/theforeman/tfm/root/usr/share/gems/gems/runcible-2.8.1/lib/runcible/base.rb:93:in block in get_response' /opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.1/lib/restclient/request.rb:807:inprocess_result’
/opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.1/lib/restclient/request.rb:725:in block in transmit' /opt/rh/rh-ruby24/root/usr/share/ruby/net/http.rb:877:instart’
/opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.1/lib/restclient/request.rb:715:in transmit' /opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.1/lib/restclient/request.rb:145:inexecute’
/opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.1/lib/restclient/request.rb:52:in execute' /opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.1/lib/restclient/resource.rb:51:inget’
/opt/theforeman/tfm/root/usr/share/gems/gems/runcible-2.8.1/lib/runcible/base.rb:92:in get_response' /opt/theforeman/tfm/root/usr/share/gems/gems/runcible-2.8.1/lib/runcible/base.rb:72:incall’
/opt/theforeman/tfm/root/usr/share/gems/gems/runcible-2.8.1/lib/runcible/resources/event_notifier.rb:48:in list' /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.8.0/app/models/katello/glue/pulp/repo.rb:36:inensure_sync_notification’
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.8.0/lib/katello/tasks/update_sync_notifications.rake:5:in block (2 levels) in <top (required)>' /opt/rh/rh-ruby24/root/usr/share/gems/gems/rake-12.0.0/lib/rake/task.rb:250:inblock in execute’
/opt/rh/rh-ruby24/root/usr/share/gems/gems/rake-12.0.0/lib/rake/task.rb:250:in each' /opt/rh/rh-ruby24/root/usr/share/gems/gems/rake-12.0.0/lib/rake/task.rb:250:inexecute’
/opt/rh/rh-ruby24/root/usr/share/gems/gems/rake-12.0.0/lib/rake/task.rb:194:in block in invoke_with_call_chain' /opt/rh/rh-ruby24/root/usr/share/ruby/monitor.rb:214:inmon_synchronize’
/opt/rh/rh-ruby24/root/usr/share/gems/gems/rake-12.0.0/lib/rake/task.rb:187:in invoke_with_call_chain' /opt/rh/rh-ruby24/root/usr/share/gems/gems/rake-12.0.0/lib/rake/task.rb:180:ininvoke’
/opt/rh/rh-ruby24/root/usr/share/gems/gems/rake-12.0.0/lib/rake/application.rb:152:in invoke_task' /opt/rh/rh-ruby24/root/usr/share/gems/gems/rake-12.0.0/lib/rake/application.rb:108:inblock (2 levels) in top_level’
/opt/rh/rh-ruby24/root/usr/share/gems/gems/rake-12.0.0/lib/rake/application.rb:108:in each' /opt/rh/rh-ruby24/root/usr/share/gems/gems/rake-12.0.0/lib/rake/application.rb:108:inblock in top_level’
/opt/rh/rh-ruby24/root/usr/share/gems/gems/rake-12.0.0/lib/rake/application.rb:117:in run_with_threads' /opt/rh/rh-ruby24/root/usr/share/gems/gems/rake-12.0.0/lib/rake/application.rb:102:intop_level’
/opt/rh/rh-ruby24/root/usr/share/gems/gems/rake-12.0.0/lib/rake/application.rb:80:in block in run' /opt/rh/rh-ruby24/root/usr/share/gems/gems/rake-12.0.0/lib/rake/application.rb:178:instandard_exception_handling’
/opt/rh/rh-ruby24/root/usr/share/gems/gems/rake-12.0.0/lib/rake/application.rb:77:in run' /opt/rh/rh-ruby24/root/usr/share/gems/gems/rake-12.0.0/exe/rake:27:in<top (required)>’
/opt/rh/rh-ruby24/root/usr/bin/rake:23:in load' /opt/rh/rh-ruby24/root/usr/bin/rake:23:in’
Tasks: TOP => katello:update_sync_notifications

And journald returns :

Oct 19 11:15:56 pulp[1564]: pulp.server.webservices.application:CRITICAL: *************************************************************
Oct 19 11:15:56 pulp[1564]: pulp.server.webservices.application:ERROR: (1564-97984) The Pulp server encountered an unexpected failure during initialization
Oct 19 11:15:56 pulp[1564]: pulp.server.webservices.application:ERROR: (1564-97984) Traceback (most recent call last):
Oct 19 11:15:56 pulp[1564]: pulp.server.webservices.application:ERROR: (1564-97984) File “/usr/lib/python2.7/site-packages/pulp/server/webservices/application.py”, line 111, in wsgi_application
Oct 19 11:15:56 pulp[1564]: pulp.server.webservices.application:ERROR: (1564-97984) _initialize_web_services()
Oct 19 11:15:56 pulp[1564]: pulp.server.webservices.application:ERROR: (1564-97984) File “/usr/lib/python2.7/site-packages/pulp/server/webservices/application.py”, line 66, in _initialize_web_services
Oct 19 11:15:56 pulp[1564]: pulp.server.webservices.application:ERROR: (1564-97984) initialization.initialize()
Oct 19 11:15:56 pulp[1564]: pulp.server.webservices.application:ERROR: (1564-97984) File “/usr/lib/python2.7/site-packages/pulp/server/initialization.py”, line 31, in initialize
Oct 19 11:15:56 pulp[1564]: pulp.server.webservices.application:ERROR: (1564-97984) db_connection.initialize()
Oct 19 11:15:56 pulp[1564]: pulp.server.webservices.application:ERROR: (1564-97984) File “/usr/lib/python2.7/site-packages/pulp/server/db/connection.py”, line 61, in initialize
Oct 19 11:15:56 pulp[1564]: pulp.server.webservices.application:ERROR: (1564-97984) raise RuntimeError("The database is already initialized. It is an error to call this "
Oct 19 11:15:56 pulp[1564]: pulp.server.webservices.application:ERROR: (1564-97984) RuntimeError: The database is already initialized. It is an error to call this function a second time.
Oct 19 11:15:56 pulp[1564]: pulp.server.webservices.application:CRITICAL: *************************************************************

I’m not able to set a new date/time for my sync-plan…

Arsene · October 19, 2018, 12:30pm

Sorry the error was due to a typo during applying patches.
It now works.

Thanks a lot.