Error while connecting multiple charge points

[ChaitanyaYeole02]

@villekr Sometimes when my ChargePoint reconnects to my CentralSystem, I get this error, is this a handshake error, and is it necessary that I get an Exception?
How to avoid this or else bypass this?

ERROR:    Exception in ASGI application
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 225, in run_asgi
    result = await self.app(self.scope, self.asgi_receive, self.asgi_send)
  File "/usr/local/lib/python3.10/site-packages/uvicorn/middleware/proxy_headers.py", line 78, in __call__
    return await self.app(scope, receive, send)
  File "/app/ocpp_asgi/app.py", line 100, in __call__
    await self.handler(scope, receive, send)
  File "/app/ocpp_asgi/app.py", line 136, in handler
    await self.on_receive(message=context.body, context=context)
  File "/app/ocpp_asgi/app.py", line 181, in on_receive
    await router.route_message(message=message, context=context)
  File "/app/ocpp_asgi/router.py", line 177, in route_message
    await self._handle_call(msg, context=context)
  File "/app/ocpp_asgi/router.py", line 255, in _handle_call
    await self._send(message=response.to_json(), is_response=True, context=context)
  File "/app/ocpp_asgi/router.py", line 307, in _send
    await context.send(message=message, is_response=is_response, context=context)
  File "/app/ocpp_asgi/app.py", line 58, in __call__
    await self.send(
  File "/usr/local/lib/python3.10/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 298, in asgi_send
    await self.send(data)  # type: ignore[arg-type]
  File "/usr/local/lib/python3.10/site-packages/websockets/legacy/protocol.py", line 632, in send
    await self.write_frame(True, opcode, data)
  File "/usr/local/lib/python3.10/site-packages/websockets/legacy/protocol.py", line 1189, in write_frame
    await self.drain()
  File "/usr/local/lib/python3.10/site-packages/websockets/legacy/protocol.py", line 1178, in drain
    await self.ensure_open()
  File "/usr/local/lib/python3.10/site-packages/websockets/legacy/protocol.py", line 921, in ensure_open
    raise self.connection_closed_exc()
websockets.exceptions.ConnectionClosedOK: received 1000 (OK); then sent 1000 (OK)
[run_asgi - 229] Exception in ASGI application
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 225, in run_asgi
    result = await self.app(self.scope, self.asgi_receive, self.asgi_send)
  File "/usr/local/lib/python3.10/site-packages/uvicorn/middleware/proxy_headers.py", line 78, in __call__
    return await self.app(scope, receive, send)
  File "/app/ocpp_asgi/app.py", line 100, in __call__
    await self.handler(scope, receive, send)
  File "/app/ocpp_asgi/app.py", line 136, in handler
    await self.on_receive(message=context.body, context=context)
  File "/app/ocpp_asgi/app.py", line 181, in on_receive
    await router.route_message(message=message, context=context)
  File "/app/ocpp_asgi/router.py", line 177, in route_message
    await self._handle_call(msg, context=context)
  File "/app/ocpp_asgi/router.py", line 255, in _handle_call
    await self._send(message=response.to_json(), is_response=True, context=context)
  File "/app/ocpp_asgi/router.py", line 307, in _send
    await context.send(message=message, is_response=is_response, context=context)
  File "/app/ocpp_asgi/app.py", line 58, in __call__
    await self.send(
  File "/usr/local/lib/python3.10/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 298, in asgi_send
    await self.send(data)  # type: ignore[arg-type]
  File "/usr/local/lib/python3.10/site-packages/websockets/legacy/protocol.py", line 632, in send
    await self.write_frame(True, opcode, data)
  File "/usr/local/lib/python3.10/site-packages/websockets/legacy/protocol.py", line 1189, in write_frame
    await self.drain()
  File "/usr/local/lib/python3.10/site-packages/websockets/legacy/protocol.py", line 1178, in drain
    await self.ensure_open()
  File "/usr/local/lib/python3.10/site-packages/websockets/legacy/protocol.py", line 921, in ensure_open
    raise self.connection_closed_exc()
websockets.exceptions.ConnectionClosedOK: received 1000 (OK); then sent 1000 (OK)
DEBUG:    = connection is CLOSED
[connection_lost - 1489] = connection is CLOSED
DEBUG:    ! failing connection with code 1006
[fail_connection - 1404] ! failing connection with code 1006
ERROR:    Exception in ASGI application
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 225, in run_asgi
    result = await self.app(self.scope, self.asgi_receive, self.asgi_send)
  File "/usr/local/lib/python3.10/site-packages/uvicorn/middleware/proxy_headers.py", line 78, in __call__
    return await self.app(scope, receive, send)
  File "/app/ocpp_asgi/app.py", line 100, in __call__
    await self.handler(scope, receive, send)
  File "/app/ocpp_asgi/app.py", line 136, in handler
    await self.on_receive(message=context.body, context=context)
  File "/app/ocpp_asgi/app.py", line 181, in on_receive
    await router.route_message(message=message, context=context)
  File "/app/ocpp_asgi/router.py", line 177, in route_message
    await self._handle_call(msg, context=context)
  File "/app/ocpp_asgi/router.py", line 255, in _handle_call
    await self._send(message=response.to_json(), is_response=True, context=context)
  File "/app/ocpp_asgi/router.py", line 307, in _send
    await context.send(message=message, is_response=is_response, context=context)
  File "/app/ocpp_asgi/app.py", line 58, in __call__
    await self.send(
  File "/usr/local/lib/python3.10/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 298, in asgi_send
    await self.send(data)  # type: ignore[arg-type]
  File "/usr/local/lib/python3.10/site-packages/websockets/legacy/protocol.py", line 632, in send
    await self.write_frame(True, opcode, data)
  File "/usr/local/lib/python3.10/site-packages/websockets/legacy/protocol.py", line 1189, in write_frame
    await self.drain()
  File "/usr/local/lib/python3.10/site-packages/websockets/legacy/protocol.py", line 1178, in drain
    await self.ensure_open()
  File "/usr/local/lib/python3.10/site-packages/websockets/legacy/protocol.py", line 921, in ensure_open
    raise self.connection_closed_exc()
websockets.exceptions.ConnectionClosedOK: received 1000 (OK); then sent 1000 (OK)
[run_asgi - 229] Exception in ASGI application
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 225, in run_asgi
    result = await self.app(self.scope, self.asgi_receive, self.asgi_send)
  File "/usr/local/lib/python3.10/site-packages/uvicorn/middleware/proxy_headers.py", line 78, in __call__
    return await self.app(scope, receive, send)
  File "/app/ocpp_asgi/app.py", line 100, in __call__
    await self.handler(scope, receive, send)
  File "/app/ocpp_asgi/app.py", line 136, in handler
    await self.on_receive(message=context.body, context=context)
  File "/app/ocpp_asgi/app.py", line 181, in on_receive
    await router.route_message(message=message, context=context)
  File "/app/ocpp_asgi/router.py", line 177, in route_message
    await self._handle_call(msg, context=context)
  File "/app/ocpp_asgi/router.py", line 255, in _handle_call
    await self._send(message=response.to_json(), is_response=True, context=context)
  File "/app/ocpp_asgi/router.py", line 307, in _send
    await context.send(message=message, is_response=is_response, context=context)
  File "/app/ocpp_asgi/app.py", line 58, in __call__
    await self.send(
  File "/usr/local/lib/python3.10/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 298, in asgi_send
    await self.send(data)  # type: ignore[arg-type]
  File "/usr/local/lib/python3.10/site-packages/websockets/legacy/protocol.py", line 632, in send
    await self.write_frame(True, opcode, data)
  File "/usr/local/lib/python3.10/site-packages/websockets/legacy/protocol.py", line 1189, in write_frame
    await self.drain()
  File "/usr/local/lib/python3.10/site-packages/websockets/legacy/protocol.py", line 1178, in drain
    await self.ensure_open()
  File "/usr/local/lib/python3.10/site-packages/websockets/legacy/protocol.py", line 921, in ensure_open
    raise self.connection_closed_exc()
websockets.exceptions.ConnectionClosedOK: received 1000 (OK); then sent 1000 (OK)

[ChaitanyaYeole02]

I am also getting this error randomly

ERROR:    Exception in ASGI application
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/uvicorn/protocols/http/h11_impl.py", line 404, in run_asgi
    result = await app(  # type: ignore[func-returns-value]
  File "/usr/local/lib/python3.10/site-packages/uvicorn/middleware/proxy_headers.py", line 78, in __call__
    return await self.app(scope, receive, send)
  File "/app/ocpp_asgi/app.py", line 100, in __call__
    await self.handler(scope, receive, send)
  File "/app/ocpp_asgi/app.py", line 130, in handler
    context: RouterContext = self._create_context(
  File "/app/ocpp_asgi/app.py", line 241, in _create_context
    http_event = json.loads(event["body"])
  File "/usr/local/lib/python3.10/json/__init__.py", line 346, in loads
    return _default_decoder.decode(s)
  File "/usr/local/lib/python3.10/json/decoder.py", line 337, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/usr/local/lib/python3.10/json/decoder.py", line 355, in raw_decode
    raise JSONDecodeError("Expecting value", s, err.value) from None
json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
[run_asgi - 409] Exception in ASGI application
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/uvicorn/protocols/http/h11_impl.py", line 404, in run_asgi
    result = await app(  # type: ignore[func-returns-value]
  File "/usr/local/lib/python3.10/site-packages/uvicorn/middleware/proxy_headers.py", line 78, in __call__
    return await self.app(scope, receive, send)
  File "/app/ocpp_asgi/app.py", line 100, in __call__
    await self.handler(scope, receive, send)
  File "/app/ocpp_asgi/app.py", line 130, in handler
    context: RouterContext = self._create_context(
  File "/app/ocpp_asgi/app.py", line 241, in _create_context
    http_event = json.loads(event["body"])
  File "/usr/local/lib/python3.10/json/__init__.py", line 346, in loads
    return _default_decoder.decode(s)
  File "/usr/local/lib/python3.10/json/decoder.py", line 337, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/usr/local/lib/python3.10/json/decoder.py", line 355, in raw_decode
    raise JSONDecodeError("Expecting value", s, err.value) from None
json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
INFO:     **.***.*.***:64188 - "GET / HTTP/1.1" 500 Internal Server Error

Before this error I saw a warning

WARNING:  Invalid HTTP request received.
[handle_events - 170] Invalid HTTP request received.

Is this something common, and how will I be able to avoid this?

[ChaitanyaYeole02]

@villekr Any suggestions?

[villekr]

First one looks like there might be some messaging going on during disconnect or over already disconnected connection. Try to be careful how you initiate messaging from on_connect. Also ensure that you update charging station's connection state on on_disconnect so that your backed doesn't try to message to disconnected instance.

Second one might be a bug in ocpp-asgi. Earlier in your logs before traceback error you should have 'scope' variable logged. What's the value in that case?

[ChaitanyaYeole02]

@villekr Please ignore the previous comment. I have created a reproducible example. If you have any doubt about this please let me know. I am just suggesting that the WebSockets library upgrades the HTTP request by itself, then why isn't this happening over here? Is this an ocpp-asgi library error or uvicorn error?

Packages Used
websocket==10.0
ocpp==0.8.3
asyncio=3.4.3

Normal WS Code

import asyncio
import logging
import websockets

logging.basicConfig(level=logging.INFO)


async def on_connect(websocket, path):
    """ For every new charge point that connects, create a ChargePoint
    instance and start listening for messages.
    """
    try:
        requested_protocols = websocket.request_headers[
            'Sec-WebSocket-Protocol']
    except KeyError:
        logging.info("Client hasn't requested any Subprotocol. "
                 "Closing Connection")
    if websocket.subprotocol:
        logging.info("Protocols Matched: %s", websocket.subprotocol)
    else:
        # In the websockets lib if no subprotocols are supported by the
        # client and the server, it proceeds without a subprotocol,
        # so we have to manually close the connection.
        logging.warning('Protocols Mismatched | Expected Subprotocols: %s,'
                        ' but client supports  %s | Closing connection',
                        websocket.available_subprotocols,
                        requested_protocols)
        return await websocket.close()


async def main():
    server = await websockets.serve(
        on_connect,
        '0.0.0.0',
        9000,
        subprotocols=['ocpp2.0.1']
    )
    logging.info("WebSocket Server Started")
    await server.wait_closed()

if __name__ == '__main__':
    asyncio.run(main())

Logs after I send an empty HTTP request through Postman HTTP Request - http://localhost:9000/

INFO:websockets.server:server listening on 0.0.0.0:9000
INFO:root:WebSocket Server Started
INFO:websockets.server:connection failed (426 Upgrade Required)
INFO:websockets.server:connection closed
INFO:websockets.server:connection failed (426 Upgrade Required)
INFO:websockets.server:connection closed

Packages Used
websocket==10.0
ocpp==0.8.3
asyncio=3.4.3
uvicorn==0.18.3
ocpp-asgi==0.2.0

Code through OCPP-ASGI

import uvicorn

from ocpp_asgi.app import ASGIApplication, RouterContext, Subprotocol
from central_system.routers.v16.provisioning_router import (router as v16_provisioning_router,)


class CentralSystem(ASGIApplication):
    """Central System is collection of routers."""

    async def on_startup(self):
        print("(CentralSystem) Startup.")

    async def on_shutdown(self):
        print("(CentralSystem) Shutdown.")

    async def on_connect(self, context: RouterContext) -> bool:
        print(
            f"(CentralSystem) Charging Station id: {context.charging_station_id} subprotocol: "
            f"{context.subprotocol} connected."
            # noqa: E501
        )
        # You can inspect context.scope["headers"] and perform eg. basic authentication
        return True

    async def on_disconnect(
            self, *, charging_station_id: str, subprotocol: Subprotocol, code: str
    ):
        ocpp_id = charging_station_id
        print(
            f"OCPP ID: {ocpp_id} subprotocol: {subprotocol} "
            f"Disconnected. Reason code: {code}"
        )


central_system = CentralSystem()
central_system.include_router(v16_provisioning_router)
if __name__ == '__main__':
    subprotocols = f"{Subprotocol.ocpp16}"
    headers = [("Sec-WebSocket-Protocol", subprotocols)]
    uvicorn.run("main-2:central_system", host="0.0.0.0", port=9000, headers=headers, workers=1, ws_ping_interval=None,
                ws_ping_timeout=None, use_colors=True, log_level='debug', timeout_keep_alive=30)

Logs after I send an empty HTTP request through Postman HTTP Request - http://localhost:9000/

C:\Users\s******5\PycharmProjects\http-error-ws\venv\Scripts\python.exe C:/Users/s******5/PycharmProjects/http-error-ws/main-2.py 
(CentralSystem) Startup.
INFO:     Started server process [10700]
[serve - 75] Started server process [10700]
INFO:     Waiting for application startup.
[startup - 47] Waiting for application startup.
INFO:     Application startup complete.
[startup - 61] Application startup complete.
INFO:     Uvicorn running on http://0.0.0.0:9000 (Press CTRL+C to quit)
[_log_started_message - 207] Uvicorn running on http://0.0.0.0:9000 (Press CTRL+C to quit)
INFO:     127.0.0.1:57534 - "GET / HTTP/1.1" 500 Internal Server Error
ERROR:    Exception in ASGI application
Traceback (most recent call last):
  File "C:\Users\s******5\PycharmProjects\http-error-ws\venv\lib\site-packages\uvicorn\protocols\http\h11_impl.py", line 404, in run_asgi
    result = await app(  # type: ignore[func-returns-value]
  File "C:\Users\s******5\PycharmProjects\http-error-ws\venv\lib\site-packages\uvicorn\middleware\proxy_headers.py", line 78, in __call__
    return await self.app(scope, receive, send)
  File "C:\Users\s******5\PycharmProjects\http-error-ws\ocpp_asgi\app.py", line 100, in __call__
    await self.handler(scope, receive, send)
  File "C:\Users\s******5\PycharmProjects\http-error-ws\ocpp_asgi\app.py", line 130, in handler
    context: RouterContext = self._create_context(
  File "C:\Users\s******5\PycharmProjects\http-error-ws\ocpp_asgi\app.py", line 232, in _create_context
    http_event = json.loads(event["body"])
  File "C:\Users\s******5\AppData\Local\Programs\Python\Python310\lib\json\__init__.py", line 346, in loads
    return _default_decoder.decode(s)
  File "C:\Users\s******5\AppData\Local\Programs\Python\Python310\lib\json\decoder.py", line 337, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "C:\Users\s******5\AppData\Local\Programs\Python\Python310\lib\json\decoder.py", line 355, in raw_decode
    raise JSONDecodeError("Expecting value", s, err.value) from None
json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
[run_asgi - 409] Exception in ASGI application
Traceback (most recent call last):
  File "C:\Users\s******5\PycharmProjects\http-error-ws\venv\lib\site-packages\uvicorn\protocols\http\h11_impl.py", line 404, in run_asgi
    result = await app(  # type: ignore[func-returns-value]
  File "C:\Users\s******5\PycharmProjects\http-error-ws\venv\lib\site-packages\uvicorn\middleware\proxy_headers.py", line 78, in __call__
    return await self.app(scope, receive, send)
  File "C:\Users\s******5\PycharmProjects\http-error-ws\ocpp_asgi\app.py", line 100, in __call__
    await self.handler(scope, receive, send)
  File "C:\Users\s******5\PycharmProjects\http-error-ws\ocpp_asgi\app.py", line 130, in handler
    context: RouterContext = self._create_context(
  File "C:\Users\s******5\PycharmProjects\http-error-ws\ocpp_asgi\app.py", line 232, in _create_context
    http_event = json.loads(event["body"])
  File "C:\Users\s******5\AppData\Local\Programs\Python\Python310\lib\json\__init__.py", line 346, in loads
    return _default_decoder.decode(s)
  File "C:\Users\s******5\AppData\Local\Programs\Python\Python310\lib\json\decoder.py", line 337, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "C:\Users\s******5\AppData\Local\Programs\Python\Python310\lib\json\decoder.py", line 355, in raw_decode
    raise JSONDecodeError("Expecting value", s, err.value) from None
json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
ERROR:    Exception in ASGI application
Traceback (most recent call last):
  File "C:\Users\s******5\PycharmProjects\http-error-ws\venv\lib\site-packages\uvicorn\protocols\http\h11_impl.py", line 404, in run_asgi
    result = await app(  # type: ignore[func-returns-value]
  File "C:\Users\s******5\PycharmProjects\http-error-ws\venv\lib\site-packages\uvicorn\middleware\proxy_headers.py", line 78, in __call__
    return await self.app(scope, receive, send)
  File "C:\Users\s******5\AppData\Local\Programs\Python\Python310\lib\json\__init__.py", line 346, in loads
    return _default_decoder.decode(s)
  File "C:\Users\s******5\AppData\Local\Programs\Python\Python310\lib\json\decoder.py", line 337, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "C:\Users\s******5\AppData\Local\Programs\Python\Python310\lib\json\decoder.py", line 355, in raw_decode
    raise JSONDecodeError("Expecting value", s, err.value) from None
json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
[run_asgi - 409] Exception in ASGI application
Traceback (most recent call last):
  File "C:\Users\s******5\PycharmProjects\http-error-ws\venv\lib\site-packages\uvicorn\protocols\http\h11_impl.py", line 404, in run_asgi
    result = await app(  # type: ignore[func-returns-value]
  File "C:\Users\s******5\PycharmProjects\http-error-ws\venv\lib\site-packages\uvicorn\middleware\proxy_headers.py", line 78, in __call__
    return await self.app(scope, receive, send)
  File "C:\Users\s******5\PycharmProjects\http-error-ws\ocpp_asgi\app.py", line 100, in __call__
    await self.handler(scope, receive, send)
  File "C:\Users\s******5\PycharmProjects\http-error-ws\ocpp_asgi\app.py", line 130, in handler
    context: RouterContext = self._create_context(
  File "C:\Users\s******5\PycharmProjects\http-error-ws\ocpp_asgi\app.py", line 232, in _create_context
    http_event = json.loads(event["body"])
  File "C:\Users\s******5\AppData\Local\Programs\Python\Python310\lib\json\__init__.py", line 346, in loads
    return _default_decoder.decode(s)
  File "C:\Users\s******5\AppData\Local\Programs\Python\Python310\lib\json\decoder.py", line 337, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "C:\Users\s******5\AppData\Local\Programs\Python\Python310\lib\json\decoder.py", line 355, in raw_decode
    raise JSONDecodeError("Expecting value", s, err.value) from None
json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
INFO:     127.0.0.1:57535 - "GET /favicon.ico HTTP/1.1" 500 Internal Server Error

Values of SCOPE, EVENT and SEND

SCOPE {'type': 'http', 'asgi': {'version': '3.0', 'spec_version': '2.3'}, 'http_version': '1.1', 'server': ('127.0.0.1', 9000), 'client': ('127.0.0.1', 57579), 'scheme': 'http', 'method': 'GET', 'root_path': '', 'path': '/favicon.ico', 'raw_path': b'/favicon.ico', 'query_string': b'', 'headers': [(b'host', b'localhost:9000'), (b'connection', b'keep-alive'), (b'sec-ch-ua', b'"Google Chrome";v="105", "Not)A;Brand";v="8", "Chromium";v="105"'), (b'sec-ch-ua-mobile', b'?0'), (b'user-agent', b'Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/105.0.0.0 Safari/537.36'), (b'sec-ch-ua-platform', b'"Windows"'), (b'accept', b'image/avif,image/webp,image/apng,image/svg+xml,image/*,*/*;q=0.8'), (b'sec-fetch-site', b'same-origin'), (b'sec-fetch-mode', b'no-cors'), (b'sec-fetch-dest', b'image'), (b'referer', b'http://localhost:9000/'), (b'accept-encoding', b'gzip, deflate, br'), (b'accept-language', b'en-US,en;q=0.9')]}
EVENT {'type': 'http.request', 'body': b'', 'more_body': False}
SEND <bound method RequestResponseCycle.send of <uvicorn.protocols.http.h11_impl.RequestResponseCycle object at 0x0000021199D3CCA0>>

[villekr]

This is fixed in #10. Now if http request has no body then return http 400 and handle that gracefully.

[ChaitanyaYeole02]

@villekr Giving a version number would be easy for everyone to track.
Like releases