Starlette: Error in app startup event is not logged and does not prevent startup

[anentropic]

Related #431 #177 and mentioned here https://github.com/encode/uvicorn/issues/333#issuecomment-484885300

Scenario:
I have a 'startup' event handler:

@app.on_event('startup')
async def startup():
    initialise()

and I am running under uvicorn for local dev just via the:

if __name__ == '__main__':
    uvicorn.run(app, host='0.0.0.0', port=8000)

If there is an uncaught exception in the startup event handler, the exception will be swallowed (not logged) and uvicorn will continue to startup.

The only anomaly seen in the logs is that uvicorn will report:

ASGI 'lifespan' protocol appears unsupported

I would like to see:

• the exception and traceback logged
• process aborted, since we haven't fully started up yet

[florimondmanca]

@anentropic I also encountered this issue before. I was able to have uvicorn show the traceback by passing lifespan="on" to uvicorn.run() — lifespan defaults to "auto" which makes uvicorn show the message you listed, see on.py-L46.

Also, in "auto" mode uvicorn doesn't abort the process, see on.py-L29.

Perhaps this is more of a uvicorn issue than a Starlette one?

[anentropic]

@florimondmanca thank you, yes that does what I want now:

ERROR    uvicorn                          Exception in 'lifespan' protocol

Traceback (most recent call last):
  File "/Users/anentropic/.virtualenvs/myproject-vPNUpldR/lib/python3.7/site-packages/uvicorn/lifespan/on.py", line 44, in main
    await app(scope, self.receive, self.send)
  File "/Users/anentropic/.virtualenvs/myproject-vPNUpldR/lib/python3.7/site-packages/uvicorn/middleware/asgi2.py", line 7, in __call__
    await instance(receive, send)
  File "/Users/anentropic/.virtualenvs/myproject-vPNUpldR/lib/python3.7/site-packages/starlette/routing.py", line 478, in asgi
    await self.startup()
  File "/Users/anentropic/.virtualenvs/myproject-vPNUpldR/lib/python3.7/site-packages/starlette/routing.py", line 461, in startup
    await handler()
  File "src/myproject/website/main.py", line 50, in startup
    raise ValueError('Startup Error')
ValueError: Startup Error
ERROR    uvicorn                          Application startup failed. Exiting.

So maybe that's enough.

ASGI docs say:

If an exception is raised when calling the application callable with a lifespan.startup message or a scope with type lifespan the server must continue but not send any lifespan events.

This allows for compatibility with applications that do not support the lifespan protocol. If you want to log an error that occurred during lifespan startup and prevent the server from starting, then send back lifespan.startup.failed instead.

I am not totally clear about the distribution of responsibilities between Uvicorn, Starlette and my app with regards to 'lifespan' events.

It seems that in lifespan="auto" mode Uvicorn is expecting either Starlette or my app to catch the exception (and send a lifespan.startup.failed event if we want to prevent startup)... so the uncaught exception is treated as a sign that the app does not support lifespan events: Uvicorn logs _"'lifespan' protocol appears unsupported"_ and continues startup, as per ASGI spec. This makes sense now.

In lifespan="on" mode the _"Exception in 'lifespan' protocol"_ error logged suggests to me that it is still the responsibility of either Starlette or my app to catch the exception and send a lifespan.startup.failed event... but in this case we have explicitly told Uvicorn that we support the lifespan protocol, so in presence of an uncaught error Uvicorn does not continue with startup but exits, logging that we violated the protocol.

The end result is what I want though so I will go with this for now.

[florimondmanca]

Thanks for this writeup! It clarifies a few things about how lifespan responsibility is distributed between the server and the app. :+1:

So, the bug is that since Starlette does support the lifespan protocol, it should handle exceptions and send back the lifespan.startup.failed event in case of an error, right?

[florimondmanca]

@anentropic I pushed two PRs to Starlette and uvicorn to fix this issue by implementing the "startup failed" part of the ASGI spec: #488 and https://github.com/encode/uvicorn/pull/350.

[kiddick]

Got same issue too btw

[kiddick]

Since I'm using unicorn via cli option --lifespan on helped me

[madkote]

Same discovered today - a fix is wanted!!!

**Describe the bug
Exceptions raised in event handlers functions are ignored.

*To Reproduce
code

def on_startup():
    print('--on-startup')
    print('**raise ERROR')
    raise ValueError('the error is not catched!')

def on_shutdown():
    print('--on-shutdown')

def register_events(app):
    app.add_event_handler('startup', on_startup)
    app.add_event_handler('shutdown', on_shutdown)
    return app

**See error

INFO: Started server process [10784]
INFO: Waiting for application startup.
DEBUG: None - ASGI [1] Started
DEBUG: None - ASGI [1] Sent {'type': 'lifespan.startup'}
--on-startup
**raise ERROR
DEBUG: None - ASGI [1] Raised exception
INFO: ASGI 'lifespan' protocol appears unsupported.
INFO: Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)
DEBUG: ('127.0.0.1', 58716) - Connected
DEBUG: ('127.0.0.1', 58716) - ASGI [2] Started
DEBUG: ('127.0.0.1', 58716) - ASGI [2] Received {'type': 'http.response.start', 'status': 200, 'headers': '<...>'}
INFO: ('127.0.0.1', 58716) - "GET /version HTTP/1.1" 200
....

**Expected behavior
The application should not start at all, if an error happened in an event - especially on startup

**Environment:
OS: Ubuntu
Starlette Version: 0.12.0
Python version, get it with: 3.7

[florimondmanca]

@madkote A fix is waiting for review in #488. Feel free to take a look!

Also, keep in mind that maintainers/contributors work on open source projects in their free time (for the large majority). A more gentle « Is there a fix for this yet? » would have been more appropriate. :-)