Bug 753680 - [RFE] Report initialisation errors in pulp log as well as Apache log
Summary: [RFE] Report initialisation errors in pulp log as well as Apache log
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Pulp
Classification: Retired
Component: z_other
Version: 2.0.6
Hardware: Unspecified
OS: Unspecified
unspecified
medium
Target Milestone: ---
: Sprint 42
Assignee: Jay Dobies
QA Contact: Preethi Thomas
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2011-11-14 05:16 UTC by Nick Coghlan
Modified: 2013-01-09 17:04 UTC (History)
1 user (show)

Fixed In Version:
Doc Type: Enhancement
Doc Text:
Clone Of:
Environment:
Last Closed: 2013-01-09 17:04:16 UTC


Attachments (Terms of Use)

Description Nick Coghlan 2011-11-14 05:16:44 UTC
In working on the generic content plugins for Pulp, I forgot that initialisation errors currently only appear in the Apache error log rather than the Pulp log.

To make the Pulp log more useful in this case, it would be nice to update pulp.server.webservices.application.wsgi_application to also record the exception in the Pulp log:

def wsgi_application():
    """
    Application factory to create, configure, and return a WSGI application
    using the web.py framework.
    @return: wsgi application callable
    """
    application = web.subdir_application(URLS)
    # TODO make debug configurable
    stack = ErrorHandlerMiddleware(application.wsgifunc(), debug=True)
    try:
        _initialize_pulp()
    except Exception as exc:
        _LOG.exception("Failed to initialize Pulp")
        raise
    return stack

(The new part is the try/except around the initialisation call)

Comment 1 Jay Dobies 2012-11-21 14:28:34 UTC
At the same time, let's use this opportunity to make it more clear that the server didn't start, similar to what Nick suggested, but I'd like to see it a step further where the initialize call has an enumerated set of exceptions that describe where it failed.

Comment 2 Jay Dobies 2012-11-21 15:36:34 UTC
QE Verification Notes:

On successful starts, only pulp.log will indicate something like the following:

2012-11-21 10:16:47,374 6538:139703320938560: pulp.server.webservices.application:INFO: application:178 *************************************************************
2012-11-21 10:16:47,374 6538:139703320938560: pulp.server.webservices.application:INFO: application:179 The Pulp server has been successfully initialized
2012-11-21 10:16:47,374 6538:139703320938560: pulp.server.webservices.application:INFO: application:180 *************************************************************

On failed starts, both pulp.log and error_log should indicate the error and traceback. It's ugly to look through based on the logging format (which I may change), but the second line is a description of what went wrong.

2012-11-21 10:16:17,663 6302:140104080852736: pulp.server.webservices.application:CRITICAL: application:164 *************************************************************
2012-11-21 10:16:17,663 6302:140104080852736: pulp.server.webservices.application:CRITICAL: application:165 The Pulp server failed to start due to the following reasons:
2012-11-21 10:16:17,663 6302:140104080852736: pulp.server.webservices.application:ERROR: application:166   One or more plugins failed to initialize. If a new type has been added, run pulp-manage-db to load the type into the database and restart the application.
Traceback (most recent call last):
  File "/home/jdob/code/pulp/pulp/platform/src/pulp/server/webservices/application.py", line 162, in wsgi_application
    # fails to start (I can't even log in),
  File "/home/jdob/code/pulp/pulp/platform/src/pulp/server/webservices/application.py", line 112, in _initialize_pulp
    plugin_api.initialize()
  File "/home/jdob/code/pulp/pulp/platform/src/pulp/plugins/loader/api.py", line 60, in initialize
    assert not _is_initialized()
InitializationException: One or more plugins failed to initialize. If a new type has been added, run pulp-manage-db to load the type into the database and restart the application.
2012-11-21 10:16:17,663 6302:140104080852736: pulp.server.webservices.application:CRITICAL: application:167 *************************************************************

Comment 3 Jay Dobies 2012-11-21 15:41:45 UTC
commit 0502f78ff320ee1a8008d4ab381cb6c6f1edba7b
commit b6b62def6780fee4780352158d06eb5c00d4c771

Comment 4 Jay Dobies 2012-11-26 15:40:07 UTC
Fixed in the 0.9 beta.

Comment 5 Preethi Thomas 2012-12-11 16:12:19 UTC
Failed start in pulp.log

2012-12-11 08:11:40,271 pulp.server.db.connection:INFO: Attempting Database connection with seeds = localhost:27017
2012-12-11 08:11:40,274 pulp.server.db.connection:CRITICAL: Database initialization failed

Successful start

2012-12-11 08:12:12,117 pulp.server.agent.direct.services:INFO: Task reply handler, started.
2012-12-11 08:12:12,117 pulp.server.agent.direct.services:INFO: AMQP reply handler started
2012-12-11 08:12:12,117 pulp.server.webservices.application:INFO: *************************************************************
2012-12-11 08:12:12,118 pulp.server.webservices.application:INFO: The Pulp server has been successfully initialized
2012-12-11 08:12:12,118 pulp.server.webservices.application:INFO: *************************************************************
2012-12-11 08:12:12,218 gofer.messaging.broker:INFO: {preethi-el6-pulp.usersys.redhat.com:5672} connected to AMQP

Failed start in error_log

[Tue Dec 11 08:14:06 2012] [error] 2012-12-11 08:14:06,449 pulp.server.db.connection:CRITICAL: Database initialization failed
[Tue Dec 11 08:14:06 2012] [error] mod_wsgi (pid=27260): Target WSGI script '/srv/pulp/webservices.wsgi' cannot be loaded as Python module.
[Tue Dec 11 08:14:06 2012] [error] mod_wsgi (pid=27260): Exception occurred processing WSGI script '/srv/pulp/webservices.wsgi'.
[Tue Dec 11 08:14:06 2012] [error] Traceback (most recent call last):
[Tue Dec 11 08:14:06 2012] [error]   File "/srv/pulp/webservices.wsgi", line 16, in <module>
[Tue Dec 11 08:14:06 2012] [error]     from pulp.server.webservices.application import wsgi_application
[Tue Dec 11 08:14:06 2012] [error]   File "/usr/lib/python2.6/site-packages/pulp/server/webservices/application.py", line 40, in <module>
[Tue Dec 11 08:14:06 2012] [error]     db_connection.initialize()
[Tue Dec 11 08:14:06 2012] [error]   File "/usr/lib/python2.6/site-packages/pulp/server/db/connection.py", line 47, in initialize
[Tue Dec 11 08:14:06 2012] [error]     _connection = pymongo.Connection(seeds)
[Tue Dec 11 08:14:06 2012] [error]   File "/usr/lib64/python2.6/site-packages/pymongo/connection.py", line 381, in __init__
[Tue Dec 11 08:14:06 2012] [error]     self.__find_node()
[Tue Dec 11 08:14:06 2012] [error]   File "/usr/lib64/python2.6/site-packages/pymongo/connection.py", line 659, in __find_node
[Tue Dec 11 08:14:06 2012] [error]     raise AutoReconnect(', '.join(errors))
[Tue Dec 11 08:14:06 2012] [error] AutoReconnect: could not connect to localhost:27017: [Errno 111] Connection refused


success

Tue Dec 11 08:15:01 2012] [notice] Apache/2.2.15 (Unix) DAV/2 mod_ssl/2.2.15 OpenSSL/1.0.0-fips mod_wsgi/3.3 Python/2.6.6 configured -- resuming normal operations

Comment 6 Preethi Thomas 2013-01-09 17:04:16 UTC
Pulp v2.0 released


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