Unable to susbscribe/register and errors 'database error: expected to be write locked for pulp_database' can be seen in logs

Problem:

Expected outcome:

Foreman and Proxy versions:

Foreman and Proxy plugin versions:

Other relevant data:
[e.g. logs from Foreman and/or the Proxy, modified templates, commands issued, etc]

Hi All,

Anyone has faced the below issue? I’v some issues with katello and unable to subscribe and get the latest updates.

# subscription-manager register --org="Default_Organization" --environment="Library"
WARNING

This system has already been registered with Red Hat using RHN Classic.

Your system is being registered again using Red Hat Subscription Management. Red Hat recommends that customers only register once.

To learn how to unregister from either service please consult this Knowledge Base Article: https://access.redhat.com/kb/docs/DOC-45563
Registering to: abdnssv02.abacus.com.sg:443/rhsm
Username: admin
Password:
Task 835f6f2c-034d-4e0e-b647-1487b8970e20: **RestClient::InternalServerError: 500 Internal Server Error**

# katello-service status
qpidd (pid  24116) is running...
tomcat6 (pid 24232) is running...                          [  OK  ]
mongod (pid  24466) is running...
elasticsearch (pid  24507) is running...
celery init v10.0.
Using config script: /etc/default/pulp_resource_manager
node resource_manager (pid 24628) is running...
celery init v10.0.
Using config script: /etc/default/pulp_workers
node reserved_resource_worker-0 is stopped...
node reserved_resource_worker-1 is stopped...
node reserved_resource_worker-2 is stopped...
node reserved_resource_worker-3 is stopped...
celery init v10.0.
Using configuration: /etc/default/pulp_workers, /etc/default/pulp_celerybeat
pulp_celerybeat is stopped.
httpd (pid  24868) is running...
dynflow_executor is running.
dynflow_executor_monitor is running.

## grep -i pulp /var/log/messages | tail -20
Jul  4 13:38:32 abdnssv02 pulp: pulp.server.webservices.middleware.exception:ERROR:     value = method(self, *args, **kwargs)
Jul  4 13:38:32 abdnssv02 pulp: pulp.server.webservices.middleware.exception:ERROR:   File "/usr/lib/python2.6/site-packages/pulp/server/webservices/controllers/consumers.py", line 103, in POST
Jul  4 13:38:32 abdnssv02 pulp: pulp.server.webservices.middleware.exception:ERROR:     rsa_pub=rsa_pub)
Jul  4 13:38:32 abdnssv02 pulp: pulp.server.webservices.middleware.exception:ERROR:   File "/usr/lib/python2.6/site-packages/pulp/server/managers/consumer/cud.py", line 92, in register
Jul  4 13:38:32 abdnssv02 pulp: pulp.server.webservices.middleware.exception:ERROR:     _id = collection.save(consumer, safe=True)
Jul  4 13:38:32 abdnssv02 pulp: pulp.server.webservices.middleware.exception:ERROR:   File "/usr/lib/python2.6/site-packages/pulp/server/db/connection.py", line 144, in retry
Jul  4 13:38:32 abdnssv02 pulp: pulp.server.webservices.middleware.exception:ERROR:     return method(*args, **kwargs)
Jul  4 13:38:32 abdnssv02 pulp: pulp.server.webservices.middleware.exception:ERROR:   File "/usr/lib64/python2.6/site-packages/pymongo/collection.py", line 269, in save
Jul  4 13:38:32 abdnssv02 pulp: pulp.server.webservices.middleware.exception:ERROR:     manipulate, safe, check_keys=check_keys, **kwargs)
Jul  4 13:38:32 abdnssv02 pulp: pulp.server.webservices.middleware.exception:ERROR:   File "/usr/lib/python2.6/site-packages/pulp/server/db/connection.py", line 144, in retry
Jul  4 13:38:32 abdnssv02 pulp: pulp.server.webservices.middleware.exception:ERROR:     return method(*args, **kwargs)
Jul  4 13:38:32 abdnssv02 pulp: pulp.server.webservices.middleware.exception:ERROR:   File "/usr/lib64/python2.6/site-packages/pymongo/collection.py", line 479, in update
Jul  4 13:38:32 abdnssv02 pulp: pulp.server.webservices.middleware.exception:ERROR:     check_keys, self.__uuid_subtype), safe)
Jul  4 13:38:32 abdnssv02 pulp: pulp.server.webservices.middleware.exception:ERROR:   File "/usr/lib/python2.6/site-packages/pulp/server/db/connection.py", line 167, in _with_end_request
Jul  4 13:38:32 abdnssv02 pulp: pulp.server.webservices.middleware.exception:ERROR:     return method(*args, **kwargs)
Jul  4 13:38:32 abdnssv02 pulp: pulp.server.webservices.middleware.exception:ERROR:   File "/usr/lib64/python2.6/site-packages/pymongo/mongo_client.py", line 920, in _send_message
Jul  4 13:38:32 abdnssv02 pulp: pulp.server.webservices.middleware.exception:ERROR:     rv = self.__check_response_to_last_error(response)
Jul  4 13:38:32 abdnssv02 pulp: pulp.server.webservices.middleware.exception:ERROR:   File "/usr/lib64/python2.6/site-packages/pymongo/mongo_client.py", line 863, in __check_response_to_last_error
Jul  4 13:38:32 abdnssv02 pulp: pulp.server.webservices.middleware.exception:ERROR:     raise OperationFailure(details["err"], details["code"])
Jul  4 13:38:32 abdnssv02 pulp: pulp.server.webservices.middleware.exception:ERROR: OperationFailure: bad offset:0 accessing file: /var/lib/mongodb/pulp_database.0 - consider repairing database

Regards,
Rafi

@Katello
Guys,

Anyone has idea on this captioned issue? Or any inputs?

**#tail -500 /var/log/foreman/production.log | more**

[ERROR 2018-07-04 14:48:56 pulp_rest  #25000] RestClient.post "https://abdnssv02.abacus.com.sg/pulp/api/v2/consumers/", "{\"id\":\"76b5fc3e-a6bb-4b15-ada0-e06f7f2e81d7\",\"display_name\":\"
abdnssv02.abacus.com.sg\"}", "Accept"=>"*/*; q=0.5, application/xml", "Accept-Encoding"=>"gzip, deflate", "Authorization"=>"OAuth oauth_body_hash=\"2jmj7l5rSw0yVb%2FvlWAYkK%2FYBwk%3D\", oau
th_consumer_key=\"katello\", oauth_nonce=\"6OlrFliuV1cRQw9JKMrkqxFXKnkwU79cCY8kKYgI\", oauth_signature=\"ij2%2BGXopCLwfXoRL7OcDTqiwfRs%3D\", oauth_signature_method=\"HMAC-SHA1\", oauth_time
stamp=\"1530686936\", oauth_version=\"1.0\"", "Content-Length"=>"86", "accept"=>"application/json", "content_type"=>"application/json", "pulp-user"=>"admin-fe70294a"
 | \n# => 500 InternalServerError | application/json 5515 bytes
 |
500 Internal Server Error (RestClient::InternalServerError)

Regards,
Rafi

It would really help if you’d filled out the template when you created this topic. We do need to know what versions of our projects you’re using - in this case, the Foreman version and the Katello version are relevant. I’m sure the @katello team will take a look when they have a moment :slight_smile:

I would recommend you try repairing your mongo database: https://docs.mongodb.com/manual/tutorial/recover-data-following-unexpected-shutdown/

Hi ,

Here is the katello version 2.1.0 and foreman version 1.7.5

rpm -qa | grep katello-2

katello-2.1.0-2.el6.noarch

rpm -qa | grep foreman-1.

foreman-1.7.5-1.el6.noarch

Regards,

Here is the overall status of pulp and mongod services.

./pulp_celerybeat status

celery init v10.0.
Using configuration: /etc/default/pulp_workers, /etc/default/pulp_celerybeat
pulp_celerybeat is stopped.

./pulp_workers status

celery init v10.0.
Using config script: /etc/default/pulp_workers
node reserved_resource_worker-0 is stopped…
node reserved_resource_worker-1 is stopped…
node reserved_resource_worker-2 is stopped…
node reserved_resource_worker-3 is stopped…

./pulp_resource_manager status

celery init v10.0.
Using config script: /etc/default/pulp_resource_manager
node resource_manager (pid 15510) is running…

./mongod status

mongod (pid 15347) is running…

I can see these messages are frequently appearing in log file now.

grep -i “pulp: celery.worker.consumer:ERROR” /var/log/messages | tail -10

Jul 6 09:49:06 abdnssv02 pulp: celery.worker.consumer:ERROR:
Jul 6 09:49:38 abdnssv02 pulp: celery.worker.consumer:ERROR: consumer: Cannot connect to qpid://guest@abdnssv02.abacus.com.sg:5671//: [Errno 1] _ssl.c:492: error:14090086:SSL routines:SSL3_GET_SERVER_CERTIFICATE:certificate verify failed.
Jul 6 09:49:38 abdnssv02 pulp: celery.worker.consumer:ERROR: Trying again in 32.00 seconds…
Jul 6 09:49:38 abdnssv02 pulp: celery.worker.consumer:ERROR:
Jul 6 09:50:10 abdnssv02 pulp: celery.worker.consumer:ERROR: consumer: Cannot connect to qpid://guest@abdnssv02.abacus.com.sg:5671//: [Errno 1] _ssl.c:492: error:14090086:SSL routines:SSL3_GET_SERVER_CERTIFICATE:certificate verify failed.
Jul 6 09:50:10 abdnssv02 pulp: celery.worker.consumer:ERROR: Trying again in 32.00 seconds…
Jul 6 09:50:10 abdnssv02 pulp: celery.worker.consumer:ERROR:
Jul 6 09:50:42 abdnssv02 pulp: celery.worker.consumer:ERROR: consumer: Cannot connect to qpid://guest@abdnssv02.abacus.com.sg:5671//: [Errno 1] _ssl.c:492: error:14090086:SSL routines:SSL3_GET_SERVER_CERTIFICATE:certificate verify failed.
Jul 6 09:50:42 abdnssv02 pulp: celery.worker.consumer:ERROR: Trying again in 32.00 seconds…
Jul 6 09:50:42 abdnssv02 pulp: celery.worker.consumer:ERROR:

tail -30 production.log

Client connected.
Connected to server.
Client connected.
Connected to server.
Client disconnected.
Client disconnected.
Connecting to database specified by database.yml
Connecting to database specified by database.yml
Creating scope :completer_scope. Overwriting existing method Location.completer_scope.
Creating scope :completer_scope. Overwriting existing method Location.completer_scope.
Creating scope :completer_scope. Overwriting existing method Organization.completer_scope.
Creating scope :completer_scope. Overwriting existing method Organization.completer_scope.
Client connected.
Connected to server.
Client connected.
Connected to server.
Client disconnected.
Client disconnected.
Connecting to database specified by database.yml
Connecting to database specified by database.yml
Creating scope :completer_scope. Overwriting existing method Location.completer_scope.
Creating scope :completer_scope. Overwriting existing method Location.completer_scope.
Creating scope :completer_scope. Overwriting existing method Organization.completer_scope.
Creating scope :completer_scope. Overwriting existing method Organization.completer_scope.
Client connected.
Connected to server.
Client connected.
Connected to server.
Client disconnected.
Client disconnected.

Guys,

any suggestions for my issue?

Regards,

Did you try @Justin_Sherrill’s suggestion from above?

Hi ,

This is the output I got after running the repair.

mongod --dbpath /var/lib/mongodb --repair

Tue Jul 10 14:37:01.624 [initandlisten] MongoDB starting : pid=8150 port=27017 dbpath=/var/lib/mongodb 64-bit host=abdnssv02.abacus.com.sg
Tue Jul 10 14:37:01.629 [initandlisten] db version v2.4.14
Tue Jul 10 14:37:01.629 [initandlisten] git version: nogitversion
Tue Jul 10 14:37:01.629 [initandlisten] build info: Linux buildvm-11.phx2.fedoraproject.org 4.7.2-201.fc24.x86_64 #1 SMP Fri Aug 26 15:58:40 UTC 2016 x86_64 BOOST_LIB_VERSION=1_41
Tue Jul 10 14:37:01.629 [initandlisten] allocator: tcmalloc
Tue Jul 10 14:37:01.629 [initandlisten] options: { dbpath: “/var/lib/mongodb”, repair: true }
Tue Jul 10 14:37:01.635 [initandlisten] exception in initAndListen: 10310 Unable to lock file: /var/lib/mongodb/mongod.lock. Is a mongod instance already running?, terminating
Tue Jul 10 14:37:01.635 dbexit:
Tue Jul 10 14:37:01.635 [initandlisten] shutdown: going to close listening sockets…
Tue Jul 10 14:37:01.635 [initandlisten] shutdown: going to flush diaglog…
Tue Jul 10 14:37:01.635 [initandlisten] shutdown: going to close sockets…
Tue Jul 10 14:37:01.635 [initandlisten] shutdown: waiting for fs preallocator…
Tue Jul 10 14:37:01.635 [initandlisten] shutdown: closing all files…
Tue Jul 10 14:37:01.635 [initandlisten] closeAllFiles() finished
Tue Jul 10 14:37:01.635 dbexit: really exiting now

Still the katello-service output remains same, even after the restart of katello.

katello-service status

qpidd (pid 9032) is running…
tomcat6 (pid 9150) is running… [ OK ]
mongod (pid 9247) is running…
elasticsearch (pid 9288) is running…
celery init v10.0.
Using config script: /etc/default/pulp_resource_manager
node resource_manager (pid 9410) is running…
celery init v10.0.
Using config script: /etc/default/pulp_workers
node reserved_resource_worker-0 is stopped…
node reserved_resource_worker-1 is stopped…
node reserved_resource_worker-2 is stopped…
node reserved_resource_worker-3 is stopped…
celery init v10.0.
Using configuration: /etc/default/pulp_workers, /etc/default/pulp_celerybeat
pulp_celerybeat is stopped.
httpd (pid 9647) is running…
dynflow_executor is running.
dynflow_executor_monitor is running.

Regards,
Rafi

The below errors are quite frequent now in messages file . Any suggestions please?

Jul 11 10:41:10 abdnssv02 pulp: qpid.messaging:WARNING: trying: abdnssv02.abacus.com.sg:5671
Jul 11 10:41:10 abdnssv02 qpidd[23142]: 2018-07-11 10:41:10 [System] error Error reading socket: Success(0)
Jul 11 10:41:10 abdnssv02 pulp: qpid.messaging:WARNING: recoverable error[attempt 8]: [Errno 1] _ssl.c:492: error:14090086:SSL routines:SSL3_GET_SERVER_CERTIFICATE:certificate verify failed
Jul 11 10:41:10 abdnssv02 pulp: qpid.messaging:WARNING: sleeping 120 seconds
Jul 11 10:41:11 abdnssv02 qpidd[23142]: 2018-07-11 10:41:11 [System] error Error reading socket: Success(0)
Jul 11 10:41:11 abdnssv02 pulp: celery.worker.consumer:ERROR: consumer: Cannot connect to qpid://guest@abdnssv02.abacus.com.sg:5671//: [Errno 1] _ssl.c:492: error:14090086:SSL routines:SSL3_GET_SERVER_CERTIFICATE:certificate verify failed.
Jul 11 10:41:11 abdnssv02 pulp: celery.worker.consumer:ERROR: Trying again in 24.00 seconds…
Jul 11 10:41:11 abdnssv02 pulp: celery.worker.consumer:ERROR:

Foreman logs below.

tail -50 /var/log/foreman/production.log

/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.3/lib/dynflow/action/progress.rb:30:in with_progress_calculation' /opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.3/lib/dynflow/action/progress.rb:16:inrun’
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.3/lib/dynflow/middleware/stack.rb:22:in call' /opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.3/lib/dynflow/middleware/stack.rb:26:inpass’
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.3/lib/dynflow/middleware.rb:16:in pass' /opt/rh/ruby193/root/usr/share/gems/gems/katello-2.1.2/app/lib/actions/middleware/keep_locale.rb:23:inblock in run’
/opt/rh/ruby193/root/usr/share/gems/gems/katello-2.1.2/app/lib/actions/middleware/keep_locale.rb:34:in with_locale' /opt/rh/ruby193/root/usr/share/gems/gems/katello-2.1.2/app/lib/actions/middleware/keep_locale.rb:23:inrun’
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.3/lib/dynflow/middleware/stack.rb:22:in call' /opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.3/lib/dynflow/middleware/world.rb:30:inexecute’
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.3/lib/dynflow/action.rb:442:in block (2 levels) in execute_run' /opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.3/lib/dynflow/action.rb:441:incatch’
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.3/lib/dynflow/action.rb:441:in block in execute_run' /opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.3/lib/dynflow/action.rb:365:incall’
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.3/lib/dynflow/action.rb:365:in block in with_error_handling' /opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.3/lib/dynflow/action.rb:365:incatch’
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.3/lib/dynflow/action.rb:365:in with_error_handling' /opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.3/lib/dynflow/action.rb:436:inexecute_run’
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.3/lib/dynflow/action.rb:230:in execute' /opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.3/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:9:inblock (2 levels) in execute’
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.3/lib/dynflow/execution_plan/steps/abstract.rb:152:in call' /opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.3/lib/dynflow/execution_plan/steps/abstract.rb:152:inwith_meta_calculation’
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.3/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:8:in block in execute' /opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.3/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:22:inopen_action’
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.3/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:7:in execute' /opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.3/lib/dynflow/executors/parallel/worker.rb:20:inblock in on_message’
/opt/rh/ruby193/root/usr/share/gems/gems/algebrick-0.4.0/lib/algebrick.rb:859:in block in assigns' /opt/rh/ruby193/root/usr/share/gems/gems/algebrick-0.4.0/lib/algebrick.rb:858:intap’
/opt/rh/ruby193/root/usr/share/gems/gems/algebrick-0.4.0/lib/algebrick.rb:858:in assigns' /opt/rh/ruby193/root/usr/share/gems/gems/algebrick-0.4.0/lib/algebrick.rb:138:inmatch_value’
/opt/rh/ruby193/root/usr/share/gems/gems/algebrick-0.4.0/lib/algebrick.rb:116:in block in match' /opt/rh/ruby193/root/usr/share/gems/gems/algebrick-0.4.0/lib/algebrick.rb:115:ineach’
/opt/rh/ruby193/root/usr/share/gems/gems/algebrick-0.4.0/lib/algebrick.rb:115:in match' /opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.3/lib/dynflow/executors/parallel/worker.rb:17:inon_message’
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.3/lib/dynflow/micro_actor.rb:82:in on_envelope' /opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.3/lib/dynflow/micro_actor.rb:72:inreceive’
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.3/lib/dynflow/micro_actor.rb:99:in block (2 levels) in run' /opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.3/lib/dynflow/micro_actor.rb:99:inloop’
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.3/lib/dynflow/micro_actor.rb:99:in block in run' /opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.3/lib/dynflow/micro_actor.rb:99:incatch’
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.3/lib/dynflow/micro_actor.rb:99:in run' /opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.3/lib/dynflow/micro_actor.rb:13:inblock in initialize’
/opt/rh/ruby193/root/usr/share/gems/gems/logging-1.8.1/lib/logging/diagnostic_context.rb:323:in call' /opt/rh/ruby193/root/usr/share/gems/gems/logging-1.8.1/lib/logging/diagnostic_context.rb:323:inblock in create_with_logging_context’
dropping event Dynflow::Executors::Abstract::Event[execution_plan_id: 4716244f-ebc3-48f6-83b3-4cefcd18ba0a, step_id: 2, event: Actions::Candlepin::ListenOnCandlepinEvents::Close, result: #Dynflow::Future:0x0000000e6e4db8] - no manager for 4716244f-ebc3-48f6-83b3-4cefcd18ba0a:2
dropping event Dynflow::Executors::Abstract::Event[execution_plan_id: 4716244f-ebc3-48f6-83b3-4cefcd18ba0a, step_id: 2, event: Actions::Candlepin::ListenOnCandlepinEvents::Close, result: #Dynflow::Future:0x0000000e6e31e8] - no manager for 4716244f-ebc3-48f6-83b3-4cefcd18ba0a:2
shutting down Core …
… Core terminated.
Disconnected from server.
Disconnected from server.

Please advice.

Regards,
Rafi

Any updates please?

Regards,
Rafi

Because you are on an ancient version your installation is probably quite old so I suspect your certificates have expired.

Any idea ,how to verify whether the certificates are expired or not in this case? And how to fix this certificate issue?

Regards,
Rafi