Fix: no exception log on Solana signature error (#451)

Problem: invalid Solana signatures are logged as exceptions, even
if the error is actually handled properly.

Solution: change log level to warning.

src/aleph/chains/solana.py

@@ -2,6 +2,7 @@
 import logging
 
 import base58
+from nacl.exceptions import BadSignatureError
 from nacl.signing import VerifyKey
 
 from aleph.chains.common import get_verification_buffer
@@ -24,28 +25,27 @@ async def verify_signature(self, message: BasePendingMessage) -> bool:
             signature = json.loads(message.signature)
             sigdata = base58.b58decode(signature["signature"])
             public_key = base58.b58decode(signature["publicKey"])
-        except Exception:
-            LOGGER.exception("Solana signature deserialization error")
+        except ValueError:
+            LOGGER.warning("Solana signature deserialization error")
             return False
 
-        try:
-            if signature.get("version", 1) != 1:
-                LOGGER.warning(
-                    "Unsupported signature version %d" % signature.get("version")
-                )
-        except Exception:
-            LOGGER.exception("Solana signature version error")
+        if signature.get("version", 1) != 1:
+            LOGGER.warning(
+                "Unsupported signature version %s" % signature.get("version")
+            )
             return False
 
         if message.sender != signature["publicKey"]:
-            LOGGER.exception("Solana signature source error")
+            LOGGER.warning("Solana signature source error")
             return False
 
         try:
             verify_key = VerifyKey(public_key)
             verification_buffer = get_verification_buffer(message)
             verif = verify_key.verify(verification_buffer, signature=sigdata)
             result = verif == verification_buffer
+        except BadSignatureError:
+            result = False
         except Exception:
             LOGGER.exception("Solana Signature verification error")
             result = False

src/aleph/schemas/base_messages.py

@@ -99,5 +99,7 @@ def check_time(cls, v, values):
         too far in the future.
         """
 
-        d = timestamp_to_datetime(v)
-        return d
+        if isinstance(v, dt.datetime):
+            return v
+
+        return timestamp_to_datetime(v)

tests/chains/test_solana.py

@@ -0,0 +1,56 @@
+import pytest
+from aleph_message.models import MessageType, Chain, ItemType
+
+from aleph.chains.solana import SolanaConnector
+from aleph.schemas.pending_messages import PendingPostMessage
+from aleph.toolkit.timestamp import timestamp_to_datetime
+
+
+@pytest.fixture
+def solana_message() -> PendingPostMessage:
+    return PendingPostMessage(
+        item_hash="6dc1b023dd1e64d28037f49a921412b3e04cf7b2b3d2537c6ae0ad2c239eae3f",
+        type=MessageType.post,
+        chain=Chain.SOL,
+        sender="AzfsDdCQp8uqzR4ProJ7yyLGKNp9iXHt92rEoiAHG4Pw",
+        signature='{"signature": "56hzHaJHH3bz1DtU6Wjhyn7eLsMCYSY4HcXkKrpwAdEHFdw7k95NPzubR3x7otstbr5JCffw81Qqpd9YUq8XJuFi","publicKey": "AzfsDdCQp8uqzR4ProJ7yyLGKNp9iXHt92rEoiAHG4Pw"}',
+        item_type=ItemType.inline,
+        item_content='{"type":"note","address":"AzfsDdCQp8uqzR4ProJ7yyLGKNp9iXHt92rEoiAHG4Pw","content":{"body":"this is a test!","title":"Test note","private":false,"notebook":null},"time":1610379947.771}',
+        time=timestamp_to_datetime(1610379947.771),
+    )
+
+
+@pytest.mark.asyncio
+async def test_solana_signature(solana_message: PendingPostMessage):
+    connector = SolanaConnector()
+    assert await connector.verify_signature(message=solana_message)
+
+
+@pytest.mark.asyncio
+@pytest.mark.parametrize(
+    "signature",
+    (
+        '{"signature": "bad-signature","publicKey": "AzfsDdCQp8uqzR4ProJ7yyLGKNp9iXHt92rEoiAHG4Pw"}',
+        '{"signature": "56hzHaJHH3bz1DtU6Wjhyn7eLsMCYSY4HcXkKrpwAdEHFdw7k95NPzubR3x7otstbr5JCffw81Qqpd9YUq8XJuFj","publicKey": "AzfsDdCQp8uqzR4ProJ7yyLGKNp9iXHt92rEoiAHG4Pw"}',
+        '{"signature": "56hzHaJHH3bz1DtU6Wjhyn7eLsMCYSY4HcXkKrpwAdEHFdw7k95NPzubR3x7otstbr5JCffw81Qqpd9YUq8XJuFj","publicKey": "BzfsDdCQp8uqzR4ProJ7yyLGKNp9iXHt92rEoiAHG4Pw"}',
+        '{{{{{',
+        "56hzHaJHH3bz1DtU6Wjhyn7eLsMCYSY4HcXkKrpwAdEHFdw7k95NPzubR3x7otstbr5JCffw81Qqpd9YUq8XJuFj",
+    ),
+    ids=(
+        "bad signature field",
+        "bad signature, closer to the original",
+        "bad public key",
+        "invalid json",
+        "just a signature",
+    ),
+)
+async def test_solana_bad_signature(
+    solana_message: PendingPostMessage, mocker, signature: str
+):
+    connector = SolanaConnector()
+    logger_mock = mocker.patch("aleph.chains.solana.LOGGER")
+
+    # Bad signature field
+    solana_message.signature = signature
+    assert not await connector.verify_signature(message=solana_message)
+    assert not logger_mock.exception.called