search

OpenLEADR / openleadr-python

Python library for OpenADR
https://openleadr.org/docs
Apache License 2.0
133 stars 51 forks source link

Error "client.py:709: KeyError" since version 0.5.12 #33

Closed benjamin-ross closed 3 years ago

benjamin-ross commented 3 years ago

Hi,

Since the introduction of version 0.5.12, our test that validates that a external VTN is up and running is failing. Here's an short example that test: 

from openleadr import OpenADRClient
import pytest
import json

VEN_NAME = "..."
VTN_ID = ""..."
VTN_URL = "..."

async def __create_registration(client):
    response_type, response_payload = await client.create_party_registration()
    # ...
    return response_payload

async def __poll(client):
    response_type, response_payload = await client.poll()
    # ...
    return response_payload

@pytest.mark.asyncio
async def test_vtn_connection():
    client = OpenADRClient(ven_name=VEN_NAME, vtn_url=VTN_URL)

    try:
        response_payload = await __create_registration(client)
        assert response_payload["vtn_id"] == VTN_ID
        assert "ven_id" in response_payload and response_payload["ven_id"]

        response_payload = await __poll(client)
        assert "ven_id" in response_payload and response_payload["ven_id"]
    finally:
        await client.stop()

Here's the stack trace from pytest: 

...
in __poll
    response_type, response_payload = await client.poll()
c:\trusted\python39\lib\site-packages\openleadr\client.py:318: in poll
    response_type, response_payload = await self._perform_request(service, message)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <openleadr.client.OpenADRClient object at 0x000001A24CF3E520>, service = 'OadrPoll'
message = '<?xml version="1.0" encoding="utf-8"?>\n<oadr:oadrPayload xmlns:oadr="http://openadr.org/oadr-2.0b/2012/07">\n<oadr:o...interop/201110"><ei:venID>{{VEN_ID}}</ei:venID></oadr:oadrPoll></oadr:oadrSignedObject>\n</oadr:oadrPayload>'

    async def _perform_request(self, service, message):
        await self._ensure_client_session()
        logger.debug(f"Client is sending {message}")
        url = f"{self.vtn_url}/{service}"
        try:
            async with self.client_session.post(url, data=message) as req:
                content = await req.read()
                if req.status != HTTPStatus.OK:
                    logger.warning(f"Non-OK status {req.status} when performing a request to {url} "
                                   f"with data {message}: {req.status} {content.decode('utf-8')}")
                    return None, {}
                logger.debug(content.decode('utf-8'))
        except aiohttp.client_exceptions.ClientConnectorError as err:
            # Could not connect to server
            logger.error(f"Could not connect to server with URL {self.vtn_url}:")
            logger.error(f"{err.__class__.__name__}: {str(err)}")
            return None, {}
        except Exception as err:
            logger.error(f"Request error {err.__class__.__name__}:{err}")
            return None, {}
        try:
            tree = validate_xml_schema(content)
            if self.vtn_fingerprint:
                validate_xml_signature(tree)
            message_type, message_payload = parse_message(content)
        except XMLSyntaxError as err:
            logger.warning(f"Incoming message did not pass XML schema validation: {err}")
            return None, {}
        except errors.FingerprintMismatch as err:
            logger.warning(err)
            return None, {}
        except InvalidSignature:
            logger.warning("Incoming message had invalid signature, ignoring.")
            return None, {}
        except Exception as err:
            logger.error(f"The incoming message could not be parsed or validated: {err}")
            return None, {}
>       if message_payload['response']['response_code'] != 200:
E       KeyError: 'response'

c:\trusted\python39\lib\site-packages\openleadr\client.py:709: KeyError
stan-janssen commented 3 years ago

Thanks for the report, I'll look into it!

stan-janssen commented 3 years ago

The strange thing is that whatever the VTN sent back passed the XML validation step, but then the message did not contain response field. I'm trying to understand what could be the problem. In the OpenLEADR test suite, hundreds of messages pass those lines of code without a problem.

If you turn on the debug logging (by calling openleadr.enable_default_logging()), and then run the test again with the -s option, you should see the XML message that comes back from the server. There is a debug line on line 684 that should print the full XML. Perhaps we can learn something from that. Can you do that and post back the result?

stan-janssen commented 3 years ago

I assumed that every oadrX response message would contain an EiResponse element, but apparently this is not the case.

oadrCreateReport, oadrCancelReport and oadrRequestReregistration are messages that might come from a VTN that do not contain these elements. The first two are usually encapsulated inside a oadrRegisteredReport or oadrUpdatedReport message, which do contain a EiResponse element, but apparently they can also be delivered separately.

I will make checking the response field optional and I will post a new version shortly.

benjamin-ross commented 3 years ago

Thank you for the quick answer! Here's more information while running it in debug mode: 

============================= test session starts =============================
platform win32 -- Python 3.9.0, pytest-6.1.2, py-1.9.0, pluggy-0.13.1
collected 1 item

test_vtn_connection.py Client is sending <?xml version="1.0" encoding="utf-8"?>
<oadr:oadrPayload xmlns:oadr="http://openadr.org/oadr-2.0b/2012/07">
<oadr:oadrSignedObject xmlns:oadr="http://openadr.org/oadr-2.0b/2012/07" oadr:Id="oadrSignedObject"><oadr:oadrCreatePartyRegistration ei:schemaVersion="2.0b" xmlns:ei="http://docs.oasis-open.org/ns/energyinterop/201110"><requestID xmlns="http://docs.oasis-open.org/ns/energyinterop/201110/payloads">b9a07b52-33c3-4add-92ca-a92a148a1f79</requestID><oadr:oadrProfileName>2.0b</oadr:oadrProfileName><oadr:oadrTransportName>simpleHttp</oadr:oadrTransportName><oadr:oadrTransportAddress>None</oadr:oadrTransportAddress><oadr:oadrReportOnly>false</oadr:oadrReportOnly><oadr:oadrXmlSignature>false</oadr:oadrXmlSignature><oadr:oadrVenName>{{VEN_NAME}}</oadr:oadrVenName><oadr:oadrHttpPullModel>true</oadr:oadrHttpPullModel></oadr:oadrCreatePartyRegistration></oadr:oadrSignedObject>
</oadr:oadrPayload>
<?xml version="1.0" encoding="UTF-8" standalone="yes"?><ns4:oadrPayload xmlns="http://www.w3.org/2000/09/xmldsig#" xmlns:ns2="http://docs.oasis-open.org/ns/energyinterop/201110" xmlns:ns3="http://docs.oasis-open.org/ns/energyinterop/201110/payloads" xmlns:ns4="http://openadr.org/oadr-2.0b/2012/07" xmlns:ns5="urn:ietf:params:xml:ns:icalendar-2.0" xmlns:ns6="http://docs.oasis-open.org/ns/emix/2011/06" xmlns:ns7="urn:ietf:params:xml:ns:icalendar-2.0:stream" xmlns:ns8="http://www.w3.org/2005/Atom" xmlns:ns9="http://docs.oasis-open.org/ns/emix/2011/06/power" xmlns:ns10="http://www.opengis.net/gml/3.2" xmlns:ns11="http://docs.oasis-open.org/ns/emix/2011/06/siscale" xmlns:ns12="http://www.w3.org/2009/xmldsig11#" xmlns:ns13="http://openadr.org/oadr-2.0b/2012/07/xmldsig-properties" xmlns:ns14="urn:un:unece:uncefact:codelist:standard:5:ISO42173A:2010-04-07"><ns4:oadrSignedObject><ns4:oadrCreatedPartyRegistration ns2:schemaVersion="2.0b"><ns2:eiResponse><ns2:responseCode>200</ns2:responseCode><ns2:responseDescription>OK</ns2:responseDescription><ns3:requestID>b9a07b52-33c3-4add-92ca-a92a148a1f79</ns3:requestID></ns2:eiResponse><ns2:registrationID>484e3cebdc2e73d84c1e</ns2:registrationID><ns2:venID>{{VEN_ID}}</ns2:venID><ns2:vtnID>{{VTN_ID}}</ns2:vtnID><ns4:oadrProfiles><ns4:oadrProfile><ns4:oadrProfileName>2.0a</ns4:oadrProfileName><ns4:oadrTransports><ns4:oadrTransport><ns4:oadrTransportName>simpleHttp</ns4:oadrTransportName></ns4:oadrTransport><ns4:oadrTransport><ns4:oadrTransportName>xmpp</ns4:oadrTransportName></ns4:oadrTransport></ns4:oadrTransports></ns4:oadrProfile><ns4:oadrProfile><ns4:oadrProfileName>2.0b</ns4:oadrProfileName><ns4:oadrTransports><ns4:oadrTransport><ns4:oadrTransportName>simpleHttp</ns4:oadrTransportName></ns4:oadrTransport><ns4:oadrTransport><ns4:oadrTransportName>xmpp</ns4:oadrTransportName></ns4:oadrTransport></ns4:oadrTransports></ns4:oadrProfile></ns4:oadrProfiles><ns4:oadrRequestedOadrPollFreq><ns5:duration>PT60S</ns5:duration></ns4:oadrRequestedOadrPollFreq></ns4:oadrCreatedPartyRegistration></ns4:oadrSignedObject></ns4:oadrPayload>
VEN is now registered with ID {{VEN_ID}}
The polling frequency is 0:01:00
Client is sending <?xml version="1.0" encoding="utf-8"?>
<oadr:oadrPayload xmlns:oadr="http://openadr.org/oadr-2.0b/2012/07">
<oadr:oadrSignedObject xmlns:oadr="http://openadr.org/oadr-2.0b/2012/07" oadr:Id="oadrSignedObject"><oadr:oadrPoll ei:schemaVersion="2.0b" xmlns:ei="http://docs.oasis-open.org/ns/energyinterop/201110"><ei:venID>{{VEN_ID}}</ei:venID></oadr:oadrPoll></oadr:oadrSignedObject>
</oadr:oadrPayload>
<?xml version="1.0" encoding="UTF-8" standalone="yes"?><ns4:oadrPayload xmlns="http://www.w3.org/2000/09/xmldsig#" xmlns:ns2="http://docs.oasis-open.org/ns/energyinterop/201110" xmlns:ns3="http://docs.oasis-open.org/ns/energyinterop/201110/payloads" xmlns:ns4="http://openadr.org/oadr-2.0b/2012/07" xmlns:ns5="urn:ietf:params:xml:ns:icalendar-2.0" xmlns:ns6="http://docs.oasis-open.org/ns/emix/2011/06" xmlns:ns7="urn:ietf:params:xml:ns:icalendar-2.0:stream" xmlns:ns8="http://www.w3.org/2005/Atom" xmlns:ns9="http://docs.oasis-open.org/ns/emix/2011/06/power" xmlns:ns10="http://www.opengis.net/gml/3.2" xmlns:ns11="http://docs.oasis-open.org/ns/emix/2011/06/siscale" xmlns:ns12="http://www.w3.org/2009/xmldsig11#" xmlns:ns13="http://openadr.org/oadr-2.0b/2012/07/xmldsig-properties" xmlns:ns14="urn:un:unece:uncefact:codelist:standard:5:ISO42173A:2010-04-07"><ns4:oadrSignedObject><ns4:oadrRegisterReport ns2:schemaVersion="2.0b"><ns3:requestID>a4b0da84a171b3cc01ed</ns3:requestID><ns2:venID>{{VEN_ID}}</ns2:venID></ns4:oadrRegisterReport></ns4:oadrSignedObject></ns4:oadrPayload>
F

..................

 __poll
    response_type, response_payload = await client.poll()
c:\trusted\python39\lib\site-packages\openleadr\client.py:318: in poll
    response_type, response_payload = await self._perform_request(service, message)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <openleadr.client.OpenADRClient object at 0x0000020DD8F17820>
service = 'OadrPoll'
message = '<?xml version="1.0" encoding="utf-8"?>\n<oadr:oadrPayload xmlns:oadr="http://openadr.org/oadr-2.0b/2012/07">\n<oadr:o...interop/201110"><ei:venID>{{VEN_ID}}</ei:venID></oadr:oadrPoll></oadr:oadrSignedObject>\n</oadr:oadrPayload>'

    async def _perform_request(self, service, message):
        await self._ensure_client_session()
        logger.debug(f"Client is sending {message}")
        url = f"{self.vtn_url}/{service}"
        try:
            async with self.client_session.post(url, data=message) as req:
                content = await req.read()
                if req.status != HTTPStatus.OK:
                    logger.warning(f"Non-OK status {req.status} when performing a request to {url} "
                                   f"with data {message}: {req.status} {content.decode('utf-8')}")
                    return None, {}
                logger.debug(content.decode('utf-8'))
        except aiohttp.client_exceptions.ClientConnectorError as err:
            # Could not connect to server
            logger.error(f"Could not connect to server with URL {self.vtn_url}:")
            logger.error(f"{err.__class__.__name__}: {str(err)}")
            return None, {}
        except Exception as err:
            logger.error(f"Request error {err.__class__.__name__}:{err}")
            return None, {}
        try:
            tree = validate_xml_schema(content)
            if self.vtn_fingerprint:
                validate_xml_signature(tree)
            message_type, message_payload = parse_message(content)
        except XMLSyntaxError as err:
            logger.warning(f"Incoming message did not pass XML schema validation: {err}")
            return None, {}
        except errors.FingerprintMismatch as err:
            logger.warning(err)
            return None, {}
        except InvalidSignature:
            logger.warning("Incoming message had invalid signature, ignoring.")
            return None, {}
        except Exception as err:
            logger.error(f"The incoming message could not be parsed or validated: {err}")
            return None, {}
>       if message_payload['response']['response_code'] != 200:
E       KeyError: 'response'

c:\trusted\python39\lib\site-packages\openleadr\client.py:709: KeyError
------------------------------ Captured log call ------------------------------
DEBUG    openleadr:client.py:674 Client is sending <?xml version="1.0" encoding="utf-8"?>
<oadr:oadrPayload xmlns:oadr="http://openadr.org/oadr-2.0b/2012/07">
<oadr:oadrSignedObject xmlns:oadr="http://openadr.org/oadr-2.0b/2012/07" oadr:Id="oadrSignedObject"><oadr:oadrCreatePartyRegistration ei:schemaVersion="2.0b" xmlns:ei="http://docs.oasis-open.org/ns/energyinterop/201110"><requestID xmlns="http://docs.oasis-open.org/ns/energyinterop/201110/payloads">b9a07b52-33c3-4add-92ca-a92a148a1f79</requestID><oadr:oadrProfileName>2.0b</oadr:oadrProfileName><oadr:oadrTransportName>simpleHttp</oadr:oadrTransportName><oadr:oadrTransportAddress>None</oadr:oadrTransportAddress><oadr:oadrReportOnly>false</oadr:oadrReportOnly><oadr:oadrXmlSignature>false</oadr:oadrXmlSignature><oadr:oadrVenName>{{VEN_NAME}}</oadr:oadrVenName><oadr:oadrHttpPullModel>true</oadr:oadrHttpPullModel></oadr:oadrCreatePartyRegistration></oadr:oadrSignedObject>
</oadr:oadrPayload>
DEBUG    openleadr:client.py:683 <?xml version="1.0" encoding="UTF-8" standalone="yes"?><ns4:oadrPayload xmlns="http://www.w3.org/2000/09/xmldsig#" xmlns:ns2="http://docs.oasis-open.org/ns/energyinterop/201110" xmlns:ns3="http://docs.oasis-open.org/ns/energyinterop/201110/payloads" xmlns:ns4="http://openadr.org/oadr-2.0b/2012/07" xmlns:ns5="urn:ietf:params:xml:ns:icalendar-2.0" xmlns:ns6="http://docs.oasis-open.org/ns/emix/2011/06" xmlns:ns7="urn:ietf:params:xml:ns:icalendar-2.0:stream" xmlns:ns8="http://www.w3.org/2005/Atom" xmlns:ns9="http://docs.oasis-open.org/ns/emix/2011/06/power" xmlns:ns10="http://www.opengis.net/gml/3.2" xmlns:ns11="http://docs.oasis-open.org/ns/emix/2011/06/siscale" xmlns:ns12="http://www.w3.org/2009/xmldsig11#" xmlns:ns13="http://openadr.org/oadr-2.0b/2012/07/xmldsig-properties" xmlns:ns14="urn:un:unece:uncefact:codelist:standard:5:ISO42173A:2010-04-07"><ns4:oadrSignedObject><ns4:oadrCreatedPartyRegistration ns2:schemaVersion="2.0b"><ns2:eiResponse><ns2:responseCode>200</ns2:responseCode><ns2:responseDescription>OK</ns2:responseDescription><ns3:requestID>b9a07b52-33c3-4add-92ca-a92a148a1f79</ns3:requestID></ns2:eiResponse><ns2:registrationID>484e3cebdc2e73d84c1e</ns2:registrationID><ns2:venID>{{VEN_ID}}</ns2:venID><ns2:vtnID>{{VTN_ID}}</ns2:vtnID><ns4:oadrProfiles><ns4:oadrProfile><ns4:oadrProfileName>2.0a</ns4:oadrProfileName><ns4:oadrTransports><ns4:oadrTransport><ns4:oadrTransportName>simpleHttp</ns4:oadrTransportName></ns4:oadrTransport><ns4:oadrTransport><ns4:oadrTransportName>xmpp</ns4:oadrTransportName></ns4:oadrTransport></ns4:oadrTransports></ns4:oadrProfile><ns4:oadrProfile><ns4:oadrProfileName>2.0b</ns4:oadrProfileName><ns4:oadrTransports><ns4:oadrTransport><ns4:oadrTransportName>simpleHttp</ns4:oadrTransportName></ns4:oadrTransport><ns4:oadrTransport><ns4:oadrTransportName>xmpp</ns4:oadrTransportName></ns4:oadrTransport></ns4:oadrTransports></ns4:oadrProfile></ns4:oadrProfiles><ns4:oadrRequestedOadrPollFreq><ns5:duration>PT60S</ns5:duration></ns4:oadrRequestedOadrPollFreq></ns4:oadrCreatedPartyRegistration></ns4:oadrSignedObject></ns4:oadrPayload>
INFO     openleadr:client.py:382 VEN is now registered with ID {{VEN_ID}}
INFO     openleadr:client.py:383 The polling frequency is 0:01:00
DEBUG    openleadr:client.py:674 Client is sending <?xml version="1.0" encoding="utf-8"?>
<oadr:oadrPayload xmlns:oadr="http://openadr.org/oadr-2.0b/2012/07">
<oadr:oadrSignedObject xmlns:oadr="http://openadr.org/oadr-2.0b/2012/07" oadr:Id="oadrSignedObject"><oadr:oadrPoll ei:schemaVersion="2.0b" xmlns:ei="http://docs.oasis-open.org/ns/energyinterop/201110"><ei:venID>{{VEN_ID}}</ei:venID></oadr:oadrPoll></oadr:oadrSignedObject>
</oadr:oadrPayload>
DEBUG    openleadr:client.py:683 <?xml version="1.0" encoding="UTF-8" standalone="yes"?><ns4:oadrPayload xmlns="http://www.w3.org/2000/09/xmldsig#" xmlns:ns2="http://docs.oasis-open.org/ns/energyinterop/201110" xmlns:ns3="http://docs.oasis-open.org/ns/energyinterop/201110/payloads" xmlns:ns4="http://openadr.org/oadr-2.0b/2012/07" xmlns:ns5="urn:ietf:params:xml:ns:icalendar-2.0" xmlns:ns6="http://docs.oasis-open.org/ns/emix/2011/06" xmlns:ns7="urn:ietf:params:xml:ns:icalendar-2.0:stream" xmlns:ns8="http://www.w3.org/2005/Atom" xmlns:ns9="http://docs.oasis-open.org/ns/emix/2011/06/power" xmlns:ns10="http://www.opengis.net/gml/3.2" xmlns:ns11="http://docs.oasis-open.org/ns/emix/2011/06/siscale" xmlns:ns12="http://www.w3.org/2009/xmldsig11#" xmlns:ns13="http://openadr.org/oadr-2.0b/2012/07/xmldsig-properties" xmlns:ns14="urn:un:unece:uncefact:codelist:standard:5:ISO42173A:2010-04-07"><ns4:oadrSignedObject><ns4:oadrRegisterReport ns2:schemaVersion="2.0b"><ns3:requestID>a4b0da84a171b3cc01ed</ns3:requestID><ns2:venID>{{VEN_ID}}</ns2:venID></ns4:oadrRegisterReport></ns4:oadrSignedObject></ns4:oadrPayload>
=========================== short test summary info ===========================
FAILED test_vtn_connection.py::test_vtn_connection[dev] - KeyError: 'response'
============================== 1 failed in 1.16s ==============================
stan-janssen commented 3 years ago

Thanks for the added info, this confirms my suspicion: the VTN is responding with a message that I did not account for (oadrRegisterReport), which has no 'response' element. Version 0.5.12 added a check for the response_code in that element to aid in debugging. I have added a fix for this problem and a test suite to prevent it ever returning ;-)

I have a question though: it is unusual for a VTN to register reports with a VEN. Do you know the use case for this? If this is something that is commonly used, I will make it a higher priority to support it in OpenLEADR (at the moment, it only supports reports from the VEN to the VTN).

Thanks!