prompt: We are currently solving the following issue within our repository. Here is the issue text:
  --- BEGIN ISSUE ---
  Misleading logs during application startup
  Hi,
  When running an application with Uvicorn, logs are a bit misleading, especially when running with "INFO" log level.
  
  Because `Waiting for application startup.` is logged before lifespan.startup with INFO level, but no information is logged to signal the end of application startup, giving the idea that the application is stuck at startup event. 'lifespan.startup.complete' can be seen using DEBUG level.
  
  No information is logged to signal when the underlying application is ready to handle requests.
  
  For example:
  ```bash
  $ uvicorn server:app --port 44777 --reload --log-level info
  
  INFO: Uvicorn running on http://127.0.0.1:44777 (Press CTRL+C to quit)
  INFO: Started reloader process [8402]
  INFO: Started server process [8406]
  INFO: Waiting for application startup.  # <-- nothing is logged after this point; the user might think the application is not ready, yet
  ```
  
  Would you accept a PR to signal with info level when application startup completes? I ask because I already have a [PR open](https://github.com/encode/uvicorn/pull/446) and I don't want to look annoying.
  
  
  --- END ISSUE ---
  
  Below are some code segments, each from a relevant file. One or more of these files may contain bugs.
  --- BEGIN FILES ---
  Path: `uvicorn/lifespan/on.py`
  Content:
  ```
  1 import asyncio
  2 
  3 STATE_TRANSITION_ERROR = "Got invalid state transition on lifespan protocol."
  4 
  5 
  6 class LifespanOn:
  7     def __init__(self, config):
  8         if not config.loaded:
  9             config.load()
  10 
  11         self.config = config
  12         self.logger = config.logger_instance
  13         self.startup_event = asyncio.Event()
  14         self.shutdown_event = asyncio.Event()
  15         self.receive_queue = asyncio.Queue()
  16         self.error_occured = False
  17         self.startup_failed = False
  18         self.should_exit = False
  19 
  20     async def startup(self):
  21         self.logger.info("Waiting for application startup.")
  22 
  23         loop = asyncio.get_event_loop()
  24         loop.create_task(self.main())
  25 
  26         await self.receive_queue.put({"type": "lifespan.startup"})
  27         await self.startup_event.wait()
  28 
  29         if self.startup_failed or (self.error_occured and self.config.lifespan == "on"):
  30             self.logger.error("Application startup failed. Exiting.")
  31             self.should_exit = True
  32 
  33     async def shutdown(self):
  34         if self.error_occured:
  35             return
  36         self.logger.info("Waiting for application shutdown.")
  37         await self.receive_queue.put({"type": "lifespan.shutdown"})
  38         await self.shutdown_event.wait()
  39 
  40     async def main(self):
  41         try:
  42             app = self.config.loaded_app
  43             scope = {"type": "lifespan"}
  44             await app(scope, self.receive, self.send)
  45         except BaseException as exc:
  46             self.asgi = None
  47             self.error_occured = True
  48             if self.startup_failed:
  49                 return
  50             if self.config.lifespan == "auto":
  51                 msg = "ASGI 'lifespan' protocol appears unsupported."
  52                 self.logger.info(msg)
  53             else:
  54                 msg = "Exception in 'lifespan' protocol\n"
  55                 self.logger.error(msg, exc_info=exc)
  56         finally:
  57             self.startup_event.set()
  58             self.shutdown_event.set()
  59 
  60     async def send(self, message):
  61         assert message["type"] in (
  62             "lifespan.startup.complete",
  63             "lifespan.startup.failed",
  64             "lifespan.shutdown.complete",
  65         )
  66 
  67         if message["type"] == "lifespan.startup.complete":
  68             assert not self.startup_event.is_set(), STATE_TRANSITION_ERROR
  69             assert not self.shutdown_event.is_set(), STATE_TRANSITION_ERROR
  70             self.startup_event.set()
  71 
  72         elif message["type"] == "lifespan.startup.failed":
  73             assert not self.startup_event.is_set(), STATE_TRANSITION_ERROR
  74             assert not self.shutdown_event.is_set(), STATE_TRANSITION_ERROR
  75             self.startup_event.set()
  76             self.startup_failed = True
  77             if message.get("message"):
  78                 self.logger.error(message["message"])
  79 
  80         elif message["type"] == "lifespan.shutdown.complete":
  81             assert self.startup_event.is_set(), STATE_TRANSITION_ERROR
  82             assert not self.shutdown_event.is_set(), STATE_TRANSITION_ERROR
  83             self.shutdown_event.set()
  84 
  85     async def receive(self):
  86         return await self.receive_queue.get()
  87
  ```
  
  Path: `uvicorn/workers.py`
  Content:
  ```
  1 import asyncio
  2 
  3 from gunicorn.workers.base import Worker
  4 from uvicorn.config import Config
  5 from uvicorn.main import Server
  6 
  7 
  8 class UvicornWorker(Worker):
  9     """
  10     A worker class for Gunicorn that interfaces with an ASGI consumer callable,
  11     rather than a WSGI callable.
  12     """
  13 
  14     CONFIG_KWARGS = {"loop": "uvloop", "http": "httptools"}
  15 
  16     def __init__(self, *args, **kwargs):
  17         super(UvicornWorker, self).__init__(*args, **kwargs)
  18 
  19         self.log.level = self.log.loglevel
  20 
  21         config_kwargs = {
  22             "app": None,
  23             "logger": self.log,
  24             "timeout_keep_alive": self.cfg.keepalive,
  25             "timeout_notify": self.timeout,
  26             "callback_notify": self.callback_notify,
  27             "limit_max_requests": self.max_requests,
  28         }
  29 
  30         if self.cfg.is_ssl:
  31             ssl_kwargs = {
  32                 "ssl_keyfile": self.cfg.ssl_options.get("keyfile"),
  33                 "ssl_certfile": self.cfg.ssl_options.get("certfile"),
  34                 "ssl_version": self.cfg.ssl_options.get("ssl_version"),
  35                 "ssl_cert_reqs": self.cfg.ssl_options.get("cert_reqs"),
  36                 "ssl_ca_certs": self.cfg.ssl_options.get("ca_certs"),
  37                 "ssl_ciphers": self.cfg.ssl_options.get("ciphers"),
  38             }
  39             config_kwargs.update(ssl_kwargs)
  40 
  41         config_kwargs.update(self.CONFIG_KWARGS)
  42 
  43         self.config = Config(**config_kwargs)
  44 
  45     def init_process(self):
  46         self.config.setup_event_loop()
  47         super(UvicornWorker, self).init_process()
  48 
  49     def init_signals(self):
  50         pass
  51 
  52     def run(self):
  53         self.config.app = self.wsgi
  54         server = Server(config=self.config)
  55         loop = asyncio.get_event_loop()
  56         loop.run_until_complete(
  57             server.serve(sockets=self.sockets, shutdown_servers=False)
  58         )
  59 
  60     async def callback_notify(self):
  61         self.notify()
  62 
  63 
  64 class UvicornH11Worker(UvicornWorker):
  65     CONFIG_KWARGS = {"loop": "asyncio", "http": "h11"}
  66
  ```
  
  Path: `uvicorn/__main__.py`
  Content:
  ```
  1 import uvicorn
  2 
  3 
  4 if __name__ == "__main__":
  5     uvicorn.main()
  6
  ```
  --- END FILES ---
  
  Please first localize the bug based on the issue statement, and then generate a patch according to the `git diff` format fenced by three backticks.
  
  Here is an example:
  
  ```diff
  diff --git a/examples/server_async.py b/examples/server_async.py
  --- a/examples/server_async.py
  +++ b/examples/server_async.py
  @@ -313,4 +313,4 @@
   
   
   if __name__ == "__main__":
  -    asyncio.run(run_async_server("."), debug=True)
  +    asyncio.run(run_async_server(), debug=True)
  diff --git a/examples/server_sync.py b/examples/server_sync.py
  --- a/examples/server_sync.py
  +++ b/examples/server_sync.py
  @@ -313,5 +313,5 @@
   
   
   if __name__ == "__main__":
  -    server = run_sync_server(".")
  +    server = run_sync_server()
       server.shutdown()
  
  ```
  
golden_diff: diff --git a/uvicorn/__main__.py b/uvicorn/__main__.py
  --- a/uvicorn/__main__.py
  +++ b/uvicorn/__main__.py
  @@ -1,5 +1,4 @@
   import uvicorn
   
  -
   if __name__ == "__main__":
       uvicorn.main()
  diff --git a/uvicorn/lifespan/on.py b/uvicorn/lifespan/on.py
  --- a/uvicorn/lifespan/on.py
  +++ b/uvicorn/lifespan/on.py
  @@ -29,6 +29,8 @@
           if self.startup_failed or (self.error_occured and self.config.lifespan == "on"):
               self.logger.error("Application startup failed. Exiting.")
               self.should_exit = True
  +        else:
  +            self.logger.info("Application startup complete.")
   
       async def shutdown(self):
           if self.error_occured:
  @@ -36,6 +38,7 @@
           self.logger.info("Waiting for application shutdown.")
           await self.receive_queue.put({"type": "lifespan.shutdown"})
           await self.shutdown_event.wait()
  +        self.logger.info("Application shutdown complete.")
   
       async def main(self):
           try:
  diff --git a/uvicorn/workers.py b/uvicorn/workers.py
  --- a/uvicorn/workers.py
  +++ b/uvicorn/workers.py
  @@ -1,6 +1,7 @@
   import asyncio
   
   from gunicorn.workers.base import Worker
  +
   from uvicorn.config import Config
   from uvicorn.main import Server
  
verification_info: {"golden_diff": "diff --git a/uvicorn/__main__.py b/uvicorn/__main__.py\n--- a/uvicorn/__main__.py\n+++ b/uvicorn/__main__.py\n@@ -1,5 +1,4 @@\n import uvicorn\n \n-\n if __name__ == \"__main__\":\n     uvicorn.main()\ndiff --git a/uvicorn/lifespan/on.py b/uvicorn/lifespan/on.py\n--- a/uvicorn/lifespan/on.py\n+++ b/uvicorn/lifespan/on.py\n@@ -29,6 +29,8 @@\n         if self.startup_failed or (self.error_occured and self.config.lifespan == \"on\"):\n             self.logger.error(\"Application startup failed. Exiting.\")\n             self.should_exit = True\n+        else:\n+            self.logger.info(\"Application startup complete.\")\n \n     async def shutdown(self):\n         if self.error_occured:\n@@ -36,6 +38,7 @@\n         self.logger.info(\"Waiting for application shutdown.\")\n         await self.receive_queue.put({\"type\": \"lifespan.shutdown\"})\n         await self.shutdown_event.wait()\n+        self.logger.info(\"Application shutdown complete.\")\n \n     async def main(self):\n         try:\ndiff --git a/uvicorn/workers.py b/uvicorn/workers.py\n--- a/uvicorn/workers.py\n+++ b/uvicorn/workers.py\n@@ -1,6 +1,7 @@\n import asyncio\n \n from gunicorn.workers.base import Worker\n+\n from uvicorn.config import Config\n from uvicorn.main import Server\n", "issue": "Misleading logs during application startup\nHi,\r\nWhen running an application with Uvicorn, logs are a bit misleading, especially when running with \"INFO\" log level.\r\n\r\nBecause `Waiting for application startup.` is logged before lifespan.startup with INFO level, but no information is logged to signal the end of application startup, giving the idea that the application is stuck at startup event. 'lifespan.startup.complete' can be seen using DEBUG level.\r\n\r\nNo information is logged to signal when the underlying application is ready to handle requests.\r\n\r\nFor example:\r\n```bash\r\n$ uvicorn server:app --port 44777 --reload --log-level info\r\n\r\nINFO: Uvicorn running on http://127.0.0.1:44777 (Press CTRL+C to quit)\r\nINFO: Started reloader process [8402]\r\nINFO: Started server process [8406]\r\nINFO: Waiting for application startup.  # <-- nothing is logged after this point; the user might think the application is not ready, yet\r\n```\r\n\r\nWould you accept a PR to signal with info level when application startup completes? I ask because I already have a [PR open](https://github.com/encode/uvicorn/pull/446) and I don't want to look annoying.\r\n\n", "before_files": [{"content": "import asyncio\n\nSTATE_TRANSITION_ERROR = \"Got invalid state transition on lifespan protocol.\"\n\n\nclass LifespanOn:\n    def __init__(self, config):\n        if not config.loaded:\n            config.load()\n\n        self.config = config\n        self.logger = config.logger_instance\n        self.startup_event = asyncio.Event()\n        self.shutdown_event = asyncio.Event()\n        self.receive_queue = asyncio.Queue()\n        self.error_occured = False\n        self.startup_failed = False\n        self.should_exit = False\n\n    async def startup(self):\n        self.logger.info(\"Waiting for application startup.\")\n\n        loop = asyncio.get_event_loop()\n        loop.create_task(self.main())\n\n        await self.receive_queue.put({\"type\": \"lifespan.startup\"})\n        await self.startup_event.wait()\n\n        if self.startup_failed or (self.error_occured and self.config.lifespan == \"on\"):\n            self.logger.error(\"Application startup failed. Exiting.\")\n            self.should_exit = True\n\n    async def shutdown(self):\n        if self.error_occured:\n            return\n        self.logger.info(\"Waiting for application shutdown.\")\n        await self.receive_queue.put({\"type\": \"lifespan.shutdown\"})\n        await self.shutdown_event.wait()\n\n    async def main(self):\n        try:\n            app = self.config.loaded_app\n            scope = {\"type\": \"lifespan\"}\n            await app(scope, self.receive, self.send)\n        except BaseException as exc:\n            self.asgi = None\n            self.error_occured = True\n            if self.startup_failed:\n                return\n            if self.config.lifespan == \"auto\":\n                msg = \"ASGI 'lifespan' protocol appears unsupported.\"\n                self.logger.info(msg)\n            else:\n                msg = \"Exception in 'lifespan' protocol\\n\"\n                self.logger.error(msg, exc_info=exc)\n        finally:\n            self.startup_event.set()\n            self.shutdown_event.set()\n\n    async def send(self, message):\n        assert message[\"type\"] in (\n            \"lifespan.startup.complete\",\n            \"lifespan.startup.failed\",\n            \"lifespan.shutdown.complete\",\n        )\n\n        if message[\"type\"] == \"lifespan.startup.complete\":\n            assert not self.startup_event.is_set(), STATE_TRANSITION_ERROR\n            assert not self.shutdown_event.is_set(), STATE_TRANSITION_ERROR\n            self.startup_event.set()\n\n        elif message[\"type\"] == \"lifespan.startup.failed\":\n            assert not self.startup_event.is_set(), STATE_TRANSITION_ERROR\n            assert not self.shutdown_event.is_set(), STATE_TRANSITION_ERROR\n            self.startup_event.set()\n            self.startup_failed = True\n            if message.get(\"message\"):\n                self.logger.error(message[\"message\"])\n\n        elif message[\"type\"] == \"lifespan.shutdown.complete\":\n            assert self.startup_event.is_set(), STATE_TRANSITION_ERROR\n            assert not self.shutdown_event.is_set(), STATE_TRANSITION_ERROR\n            self.shutdown_event.set()\n\n    async def receive(self):\n        return await self.receive_queue.get()\n", "path": "uvicorn/lifespan/on.py"}, {"content": "import asyncio\n\nfrom gunicorn.workers.base import Worker\nfrom uvicorn.config import Config\nfrom uvicorn.main import Server\n\n\nclass UvicornWorker(Worker):\n    \"\"\"\n    A worker class for Gunicorn that interfaces with an ASGI consumer callable,\n    rather than a WSGI callable.\n    \"\"\"\n\n    CONFIG_KWARGS = {\"loop\": \"uvloop\", \"http\": \"httptools\"}\n\n    def __init__(self, *args, **kwargs):\n        super(UvicornWorker, self).__init__(*args, **kwargs)\n\n        self.log.level = self.log.loglevel\n\n        config_kwargs = {\n            \"app\": None,\n            \"logger\": self.log,\n            \"timeout_keep_alive\": self.cfg.keepalive,\n            \"timeout_notify\": self.timeout,\n            \"callback_notify\": self.callback_notify,\n            \"limit_max_requests\": self.max_requests,\n        }\n\n        if self.cfg.is_ssl:\n            ssl_kwargs = {\n                \"ssl_keyfile\": self.cfg.ssl_options.get(\"keyfile\"),\n                \"ssl_certfile\": self.cfg.ssl_options.get(\"certfile\"),\n                \"ssl_version\": self.cfg.ssl_options.get(\"ssl_version\"),\n                \"ssl_cert_reqs\": self.cfg.ssl_options.get(\"cert_reqs\"),\n                \"ssl_ca_certs\": self.cfg.ssl_options.get(\"ca_certs\"),\n                \"ssl_ciphers\": self.cfg.ssl_options.get(\"ciphers\"),\n            }\n            config_kwargs.update(ssl_kwargs)\n\n        config_kwargs.update(self.CONFIG_KWARGS)\n\n        self.config = Config(**config_kwargs)\n\n    def init_process(self):\n        self.config.setup_event_loop()\n        super(UvicornWorker, self).init_process()\n\n    def init_signals(self):\n        pass\n\n    def run(self):\n        self.config.app = self.wsgi\n        server = Server(config=self.config)\n        loop = asyncio.get_event_loop()\n        loop.run_until_complete(\n            server.serve(sockets=self.sockets, shutdown_servers=False)\n        )\n\n    async def callback_notify(self):\n        self.notify()\n\n\nclass UvicornH11Worker(UvicornWorker):\n    CONFIG_KWARGS = {\"loop\": \"asyncio\", \"http\": \"h11\"}\n", "path": "uvicorn/workers.py"}, {"content": "import uvicorn\n\n\nif __name__ == \"__main__\":\n    uvicorn.main()\n", "path": "uvicorn/__main__.py"}], "after_files": [{"content": "import asyncio\n\nSTATE_TRANSITION_ERROR = \"Got invalid state transition on lifespan protocol.\"\n\n\nclass LifespanOn:\n    def __init__(self, config):\n        if not config.loaded:\n            config.load()\n\n        self.config = config\n        self.logger = config.logger_instance\n        self.startup_event = asyncio.Event()\n        self.shutdown_event = asyncio.Event()\n        self.receive_queue = asyncio.Queue()\n        self.error_occured = False\n        self.startup_failed = False\n        self.should_exit = False\n\n    async def startup(self):\n        self.logger.info(\"Waiting for application startup.\")\n\n        loop = asyncio.get_event_loop()\n        loop.create_task(self.main())\n\n        await self.receive_queue.put({\"type\": \"lifespan.startup\"})\n        await self.startup_event.wait()\n\n        if self.startup_failed or (self.error_occured and self.config.lifespan == \"on\"):\n            self.logger.error(\"Application startup failed. Exiting.\")\n            self.should_exit = True\n        else:\n            self.logger.info(\"Application startup complete.\")\n\n    async def shutdown(self):\n        if self.error_occured:\n            return\n        self.logger.info(\"Waiting for application shutdown.\")\n        await self.receive_queue.put({\"type\": \"lifespan.shutdown\"})\n        await self.shutdown_event.wait()\n        self.logger.info(\"Application shutdown complete.\")\n\n    async def main(self):\n        try:\n            app = self.config.loaded_app\n            scope = {\"type\": \"lifespan\"}\n            await app(scope, self.receive, self.send)\n        except BaseException as exc:\n            self.asgi = None\n            self.error_occured = True\n            if self.startup_failed:\n                return\n            if self.config.lifespan == \"auto\":\n                msg = \"ASGI 'lifespan' protocol appears unsupported.\"\n                self.logger.info(msg)\n            else:\n                msg = \"Exception in 'lifespan' protocol\\n\"\n                self.logger.error(msg, exc_info=exc)\n        finally:\n            self.startup_event.set()\n            self.shutdown_event.set()\n\n    async def send(self, message):\n        assert message[\"type\"] in (\n            \"lifespan.startup.complete\",\n            \"lifespan.startup.failed\",\n            \"lifespan.shutdown.complete\",\n        )\n\n        if message[\"type\"] == \"lifespan.startup.complete\":\n            assert not self.startup_event.is_set(), STATE_TRANSITION_ERROR\n            assert not self.shutdown_event.is_set(), STATE_TRANSITION_ERROR\n            self.startup_event.set()\n\n        elif message[\"type\"] == \"lifespan.startup.failed\":\n            assert not self.startup_event.is_set(), STATE_TRANSITION_ERROR\n            assert not self.shutdown_event.is_set(), STATE_TRANSITION_ERROR\n            self.startup_event.set()\n            self.startup_failed = True\n            if message.get(\"message\"):\n                self.logger.error(message[\"message\"])\n\n        elif message[\"type\"] == \"lifespan.shutdown.complete\":\n            assert self.startup_event.is_set(), STATE_TRANSITION_ERROR\n            assert not self.shutdown_event.is_set(), STATE_TRANSITION_ERROR\n            self.shutdown_event.set()\n\n    async def receive(self):\n        return await self.receive_queue.get()\n", "path": "uvicorn/lifespan/on.py"}, {"content": "import asyncio\n\nfrom gunicorn.workers.base import Worker\n\nfrom uvicorn.config import Config\nfrom uvicorn.main import Server\n\n\nclass UvicornWorker(Worker):\n    \"\"\"\n    A worker class for Gunicorn that interfaces with an ASGI consumer callable,\n    rather than a WSGI callable.\n    \"\"\"\n\n    CONFIG_KWARGS = {\"loop\": \"uvloop\", \"http\": \"httptools\"}\n\n    def __init__(self, *args, **kwargs):\n        super(UvicornWorker, self).__init__(*args, **kwargs)\n\n        self.log.level = self.log.loglevel\n\n        config_kwargs = {\n            \"app\": None,\n            \"logger\": self.log,\n            \"timeout_keep_alive\": self.cfg.keepalive,\n            \"timeout_notify\": self.timeout,\n            \"callback_notify\": self.callback_notify,\n            \"limit_max_requests\": self.max_requests,\n        }\n\n        if self.cfg.is_ssl:\n            ssl_kwargs = {\n                \"ssl_keyfile\": self.cfg.ssl_options.get(\"keyfile\"),\n                \"ssl_certfile\": self.cfg.ssl_options.get(\"certfile\"),\n                \"ssl_version\": self.cfg.ssl_options.get(\"ssl_version\"),\n                \"ssl_cert_reqs\": self.cfg.ssl_options.get(\"cert_reqs\"),\n                \"ssl_ca_certs\": self.cfg.ssl_options.get(\"ca_certs\"),\n                \"ssl_ciphers\": self.cfg.ssl_options.get(\"ciphers\"),\n            }\n            config_kwargs.update(ssl_kwargs)\n\n        config_kwargs.update(self.CONFIG_KWARGS)\n\n        self.config = Config(**config_kwargs)\n\n    def init_process(self):\n        self.config.setup_event_loop()\n        super(UvicornWorker, self).init_process()\n\n    def init_signals(self):\n        pass\n\n    def run(self):\n        self.config.app = self.wsgi\n        server = Server(config=self.config)\n        loop = asyncio.get_event_loop()\n        loop.run_until_complete(\n            server.serve(sockets=self.sockets, shutdown_servers=False)\n        )\n\n    async def callback_notify(self):\n        self.notify()\n\n\nclass UvicornH11Worker(UvicornWorker):\n    CONFIG_KWARGS = {\"loop\": \"asyncio\", \"http\": \"h11\"}\n", "path": "uvicorn/workers.py"}, {"content": "import uvicorn\n\nif __name__ == \"__main__\":\n    uvicorn.main()\n", "path": "uvicorn/__main__.py"}]}