Skip to content

Commit

Permalink
Merge pull request #8 from elahd/quieter-logging
Browse files Browse the repository at this point in the history 
Quieter logging.
  • Loading branch information
@elahd
elahd authored Jun 21, 2022
2 parents caa3521 + 2c3785a commit 1eb60b7
Show file tree
Hide file tree
Showing 3 changed files with 68 additions and 34 deletions.
32 changes: 19 additions & 13 deletions pylaundry/__init__.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -16,6 +16,7 @@
from .const import APPKEY
from .const import AUTH_TOKEN_KEY
from .const import EMPTY_AUTH_TOKEN
from .const import LOG_LEVEL_TRACE
from .const import REFRESH_REQUEST_PREHASH_SUFFIX
from .const import RESULT_CODE_KEY
from .const import RESULT_TEXT_KEY
Expand All @@ -28,7 +29,7 @@
from .exceptions import UnexpectedError
from .helpers import MessagePacker

__version__ = "v0.1.1"
__version__ = "v0.1.2"

log = logging.getLogger(__name__)

Expand Down Expand Up @@ -149,13 +150,13 @@ async def async_refresh(self) -> None:

secret_raw = f"{self.profile.user_id}{REFRESH_REQUEST_PREHASH_SUFFIX}"

log.debug("Secret Raw:\n%s\n\n", secret_raw)
log.log(LOG_LEVEL_TRACE, "Secret Raw:\n%s\n\n", secret_raw)

hash_result = hashlib.md5(bytes(secret_raw, "utf-8")) # nosec

secret_hash = hash_result.hexdigest()

log.debug("Secret Hash:\n%s\n\n", secret_hash)
log.log(LOG_LEVEL_TRACE, "Secret Hash:\n%s\n\n", secret_hash)

request_data = ["ConsolidatedRefresh", secret_hash, self.profile.user_id]

Expand Down Expand Up @@ -225,16 +226,18 @@ async def _send_request(self, request_json: str, no_retry: bool = False) -> dict
"Content-Type": "application/x-www-form-urlencoded",
}

log.debug("==============[ BUILDING REQUEST BEGIN ]==============")
log.debug("** REQUEST HEADERS **")
log.debug(request_headers)
log.log(
LOG_LEVEL_TRACE, "==============[ BUILDING REQUEST BEGIN ]=============="
)
log.log(LOG_LEVEL_TRACE, "** REQUEST HEADERS **")
log.log(LOG_LEVEL_TRACE, request_headers)

request_body = f"CP_REQ_DATA={packed_request_data}"

log.debug("** REQUEST BODY **")
log.debug(request_body)
log.log(LOG_LEVEL_TRACE, "** REQUEST BODY **")
log.log(LOG_LEVEL_TRACE, request_body)

log.debug("==============[ BUILDING REQUEST END ]==============")
log.log(LOG_LEVEL_TRACE, "==============[ BUILDING REQUEST END ]==============")

try:
async with self._websession.post(
Expand All @@ -252,7 +255,7 @@ async def _send_request(self, request_json: str, no_retry: bool = False) -> dict

raise CommunicationError from err

log.debug("RAW SERVER RESPONSE:\n%s\n\n", raw_response)
log.log(LOG_LEVEL_TRACE, "RAW SERVER RESPONSE:\n%s\n\n", raw_response)

#
# Validate response format.
Expand Down Expand Up @@ -281,7 +284,7 @@ async def _send_request(self, request_json: str, no_retry: bool = False) -> dict
if not unpacked_content:
raise UnexpectedError("Missing unpacked content.")

log.debug("UNPACKED RESPONSE CONTENT:\n%s\n\n", unpacked_content)
log.log(LOG_LEVEL_TRACE, "UNPACKED RESPONSE CONTENT:\n%s\n\n", unpacked_content)

response_code = unpacked_content.get(RESULT_CODE_KEY)

Expand All @@ -295,6 +298,7 @@ async def _send_request(self, request_json: str, no_retry: bool = False) -> dict
)
or (response_code == ServerResponseCodes.INPUT_MALFORMED and no_retry)
):
log.debug("UNPACKED RESPONSE CONTENT:\n%s\n\n", unpacked_content)
raise Rejected

if response_code == ServerResponseCodes.INPUT_MALFORMED:
Expand All @@ -311,7 +315,7 @@ async def _send_request(self, request_json: str, no_retry: bool = False) -> dict
except Exception as err:
raise Rejected("Request failed even after re-trying login.") from err

await self._send_request(request_json=request_json, no_retry=True)
return await self._send_request(request_json=request_json, no_retry=True)

if response_code == ServerResponseCodes.INVALID_CREDENTIALS:
raise AuthenticationError
Expand All @@ -324,6 +328,8 @@ async def _send_request(self, request_json: str, no_retry: bool = False) -> dict
)
raise UnexpectedError

log.debug("EXTRACTED RESPONSE CONTENT:\n%s\n\n", unpacked_content)
log.log(
LOG_LEVEL_TRACE, "EXTRACTED RESPONSE CONTENT:\n%s\n\n", unpacked_content
)

return unpacked_content
2 changes: 2 additions & 0 deletions pylaundry/const.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -37,3 +37,5 @@ class ServerResponseCodes(IntEnum):
AES_SUFFIX_PREAUTH = ( # Appended to random request UUID before further processing into AES key. Used for authentication requests only.
"R&%76mhK"
)

LOG_LEVEL_TRACE = 5
68 changes: 47 additions & 21 deletions pylaundry/helpers.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -15,6 +15,7 @@

from .const import AES_IV
from .const import AES_SUFFIX_PREAUTH
from .const import LOG_LEVEL_TRACE
from .exceptions import MessagePackerError

log = logging.getLogger(__name__)
Expand All @@ -31,24 +32,34 @@ def unpack_server_response(response_body: bytes) -> dict | None:
# 1. Base64 decode.
# 2. gzip decompress.

log.debug("==============[ UNPACKING RESPONSE BEGIN ]==============")
log.log(
LOG_LEVEL_TRACE, "==============[ UNPACKING RESPONSE BEGIN ]=============="
)

decoded_as_bytes = base64.standard_b64decode(response_body)

log.debug("Base64Decode Bytes -> Bytes:\n%s\n\n", decoded_as_bytes.hex())
log.log(
LOG_LEVEL_TRACE,
"Base64Decode Bytes -> Bytes:\n%s\n\n",
decoded_as_bytes.hex(),
)

gunzipped_as_bytes = gzip.decompress(decoded_as_bytes)

log.debug("gunzip Bytes -> Bytes:\n%s\n\n", decoded_as_bytes.hex())
log.log(
LOG_LEVEL_TRACE, "gunzip Bytes -> Bytes:\n%s\n\n", decoded_as_bytes.hex()
)

try:
json_response = json.loads(str(gunzipped_as_bytes, "utf-8"))
except ValueError as err:
raise err

log.debug("UNPACKED RESPONSE:\n%s\n\n", json_response)
log.log(LOG_LEVEL_TRACE, "UNPACKED RESPONSE:\n%s\n\n", json_response)

log.debug("==============[ UNPACKING RESPONSE END ]==============")
log.log(
LOG_LEVEL_TRACE, "==============[ UNPACKING RESPONSE END ]=============="
)

return json_response if isinstance(json_response, dict) else None

Expand All @@ -71,14 +82,16 @@ def pack_client_request(
# 4. Base64 encode, again.
# 5. URL encode.

log.debug("==============[ PACKING REQUEST BEGIN ]==============")
log.log(
LOG_LEVEL_TRACE, "==============[ PACKING REQUEST BEGIN ]=============="
)

log.debug("Original Request Body:\n%s\n\n", request_body)
log.log(LOG_LEVEL_TRACE, "Original Request Body:\n%s\n\n", request_body)

if not new_request_id:
new_request_id = str(uuid.uuid4())

log.debug("New Request ID: %s", new_request_id)
log.log(LOG_LEVEL_TRACE, "New Request ID: %s", new_request_id)

key = MessagePacker._generate_aes_key(
new_request_id=new_request_id, first_request_id=first_request_id
Expand All @@ -87,7 +100,7 @@ def pack_client_request(
# PKCS#7 Pad
padded_request = MessagePacker._pkcs7_pad(bytes(str(request_body), "utf-8"))

log.debug("Padded Request:\n%s\n\n", padded_request)
log.log(LOG_LEVEL_TRACE, "Padded Request:\n%s\n\n", padded_request)

# AES Encrypt
cipher = Cipher(algorithms.AES(key), modes.CBC(AES_IV))
Expand All @@ -96,7 +109,8 @@ def pack_client_request(
encryptor.update(bytes(padded_request)) + encryptor.finalize()
)

log.debug(
log.log(
LOG_LEVEL_TRACE,
"Encrypted Request:\n%s\n\n",
MessagePacker._format_hex(encrypted_request),
)
Expand All @@ -106,14 +120,14 @@ def pack_client_request(
base64.b64encode(encrypted_request)
)

log.debug("Base64 Encoded Request:\n%s\n\n", b64_encoded_request)
log.log(LOG_LEVEL_TRACE, "Base64 Encoded Request:\n%s\n\n", b64_encoded_request)

# URL Encode
url_encoded_request = urllib.parse.quote(b64_encoded_request)

log.debug("URL Encoded Request:\n%s\n\n", url_encoded_request)
log.log(LOG_LEVEL_TRACE, "URL Encoded Request:\n%s\n\n", url_encoded_request)

log.debug("==============[ PACKING REQUEST END ]==============")
log.log(LOG_LEVEL_TRACE, "==============[ PACKING REQUEST END ]==============")

return (str(new_request_id), url_encoded_request)

Expand All @@ -134,19 +148,23 @@ def unpack_client_request(
# URL Decode
url_decoded_request = urllib.parse.unquote(request_body)

log.debug(
"[unpack_client_request] URL Decoded Request:\n%s\n\n", url_decoded_request
log.log(
LOG_LEVEL_TRACE,
"[unpack_client_request] URL Decoded Request:\n%s\n\n",
url_decoded_request,
)

# 2x Base 64 Decode
b64_decoded_request = base64.b64decode(base64.b64decode(url_decoded_request))

log.debug(
log.log(
LOG_LEVEL_TRACE,
"[unpack_client_request] First Base64 Decoded Request:\n%s\n\n",
base64.b64decode(url_decoded_request),
)

log.debug(
log.log(
LOG_LEVEL_TRACE,
"[unpack_client_request] Second Base64 Decoded Request:\n%s\n\n",
MessagePacker._format_hex(b64_decoded_request),
)
Expand All @@ -156,7 +174,8 @@ def unpack_client_request(
decryptor = cipher.decryptor()
decrypted_request = decryptor.update(b64_decoded_request) + decryptor.finalize()

log.debug(
log.log(
LOG_LEVEL_TRACE,
"[unpack_client_request] Decrypted Request:\n%s\n\n",
decrypted_request.hex(),
)
Expand All @@ -167,7 +186,11 @@ def unpack_client_request(
except UnicodeDecodeError as err:
raise MessagePackerError("Error unpadding message.") from err

log.debug("[unpack_client_request] Unpadded Request:\n%s\n\n", unpadded_request)
log.log(
LOG_LEVEL_TRACE,
"[unpack_client_request] Unpadded Request:\n%s\n\n",
unpadded_request,
)

return str(unpadded_request, "utf-8")

Expand Down Expand Up @@ -212,8 +235,11 @@ def _generate_aes_key(

key_bytes = bytes(key_str, "utf-8")

log.debug(
"Encryption Key: %s (%s)", key_str, MessagePacker._format_hex(key_bytes)
log.log(
LOG_LEVEL_TRACE,
"Encryption Key: %s (%s)",
key_str,
MessagePacker._format_hex(key_bytes),
)

return key_bytes
Expand Down

0 comments on commit 1eb60b7

Please sign in to comment.