Browse Source

* sane log messages: SSUSession.cpp

pull/317/head
hagen 9 years ago
parent
commit
facc5f8aa7
  1. 96
      SSUSession.cpp

96
SSUSession.cpp

@ -70,7 +70,7 @@ namespace transport
nonZero++; nonZero++;
if (nonZero - sharedKey > 32) if (nonZero - sharedKey > 32)
{ {
LogPrint ("First 32 bytes of shared key is all zeros. Ignored"); LogPrint (eLogWarning, "SSU: first 32 bytes of shared key is all zeros. Ignored");
return; return;
} }
} }
@ -90,7 +90,7 @@ namespace transport
if (m_State == eSessionStateIntroduced) if (m_State == eSessionStateIntroduced)
{ {
// HolePunch received // HolePunch received
LogPrint ("SSU HolePunch of ", len, " bytes received"); LogPrint (eLogDebug, "SSU: HolePunch of ", len, " bytes received");
m_State = eSessionStateUnknown; m_State = eSessionStateUnknown;
Connect (); Connect ();
} }
@ -120,7 +120,7 @@ namespace transport
Decrypt (buf, len, address->key); Decrypt (buf, len, address->key);
else else
{ {
LogPrint (eLogError, "MAC verification failed ", len, " bytes from ", senderEndpoint); LogPrint (eLogError, "SSU: MAC verification failed ", len, " bytes from ", senderEndpoint);
m_Server.DeleteSession (shared_from_this ()); m_Server.DeleteSession (shared_from_this ());
return; return;
} }
@ -166,12 +166,12 @@ namespace transport
ProcessSessionConfirmed (buf, len); // buf with header ProcessSessionConfirmed (buf, len); // buf with header
break; break;
case PAYLOAD_TYPE_PEER_TEST: case PAYLOAD_TYPE_PEER_TEST:
LogPrint (eLogDebug, "SSU peer test received"); LogPrint (eLogDebug, "SSU: peer test received");
ProcessPeerTest (buf + headerSize, len - headerSize, senderEndpoint); ProcessPeerTest (buf + headerSize, len - headerSize, senderEndpoint);
break; break;
case PAYLOAD_TYPE_SESSION_DESTROYED: case PAYLOAD_TYPE_SESSION_DESTROYED:
{ {
LogPrint (eLogDebug, "SSU session destroy received"); LogPrint (eLogDebug, "SSU: session destroy received");
m_Server.DeleteSession (shared_from_this ()); m_Server.DeleteSession (shared_from_this ());
break; break;
} }
@ -181,21 +181,21 @@ namespace transport
m_Server.DeleteSession (shared_from_this ()); m_Server.DeleteSession (shared_from_this ());
break; break;
case PAYLOAD_TYPE_RELAY_REQUEST: case PAYLOAD_TYPE_RELAY_REQUEST:
LogPrint (eLogDebug, "SSU relay request received"); LogPrint (eLogDebug, "SSU: relay request received");
ProcessRelayRequest (buf + headerSize, len - headerSize, senderEndpoint); ProcessRelayRequest (buf + headerSize, len - headerSize, senderEndpoint);
break; break;
case PAYLOAD_TYPE_RELAY_INTRO: case PAYLOAD_TYPE_RELAY_INTRO:
LogPrint (eLogDebug, "SSU relay intro received"); LogPrint (eLogDebug, "SSU: relay intro received");
ProcessRelayIntro (buf + headerSize, len - headerSize); ProcessRelayIntro (buf + headerSize, len - headerSize);
break; break;
default: default:
LogPrint (eLogWarning, "Unexpected SSU payload type ", (int)header->GetPayloadType ()); LogPrint (eLogWarning, "SSU: Unexpected payload type ", (int)header->GetPayloadType ());
} }
} }
void SSUSession::ProcessSessionRequest (const uint8_t * buf, size_t len, const boost::asio::ip::udp::endpoint& senderEndpoint) void SSUSession::ProcessSessionRequest (const uint8_t * buf, size_t len, const boost::asio::ip::udp::endpoint& senderEndpoint)
{ {
LogPrint (eLogDebug, "Session request received"); LogPrint (eLogDebug, "SSU message: session request");
m_RemoteEndpoint = senderEndpoint; m_RemoteEndpoint = senderEndpoint;
if (!m_DHKeysPair) if (!m_DHKeysPair)
m_DHKeysPair = transports.GetNextDHKeysPair (); m_DHKeysPair = transports.GetNextDHKeysPair ();
@ -207,11 +207,11 @@ namespace transport
{ {
if (!IsOutgoing () || !m_DHKeysPair) if (!IsOutgoing () || !m_DHKeysPair)
{ {
LogPrint (eLogWarning, "Unsolicited session created message"); LogPrint (eLogWarning, "SSU: Unsolicited session created message");
return; return;
} }
LogPrint (eLogDebug, "Session created received"); LogPrint (eLogDebug, "SSU message: session created");
m_Timer.cancel (); // connect timer m_Timer.cancel (); // connect timer
SignedData s; // x,y, our IP, our port, remote IP, remote port, relayTag, signed on time SignedData s; // x,y, our IP, our port, remote IP, remote port, relayTag, signed on time
auto headerSize = GetSSUHeaderSize (buf); auto headerSize = GetSSUHeaderSize (buf);
@ -247,7 +247,7 @@ namespace transport
uint16_t ourPort = bufbe16toh (payload); uint16_t ourPort = bufbe16toh (payload);
s.Insert (payload, 2); // our port s.Insert (payload, 2); // our port
payload += 2; // port payload += 2; // port
LogPrint ("Our external address is ", ourIP.to_string (), ":", ourPort); LogPrint (eLogInfo, "SSU: Our external address is ", ourIP.to_string (), ":", ourPort);
i2p::context.UpdateAddress (ourIP); i2p::context.UpdateAddress (ourIP);
if (m_RemoteEndpoint.address ().is_v4 ()) if (m_RemoteEndpoint.address ().is_v4 ())
s.Insert (m_RemoteEndpoint.address ().to_v4 ().to_bytes ().data (), 4); // remote IP v4 s.Insert (m_RemoteEndpoint.address ().to_v4 ().to_bytes ().data (), 4); // remote IP v4
@ -267,18 +267,18 @@ namespace transport
m_SessionKeyDecryption.Decrypt (payload, signatureLen, payload); // TODO: non-const payload m_SessionKeyDecryption.Decrypt (payload, signatureLen, payload); // TODO: non-const payload
// verify // verify
if (!s.Verify (m_RemoteIdentity, payload)) if (!s.Verify (m_RemoteIdentity, payload))
LogPrint (eLogError, "Session created SSU signature verification failed"); LogPrint (eLogError, "SSU: message 'created' signature verification failed");
SendSessionConfirmed (y, ourAddress, addressSize + 2); SendSessionConfirmed (y, ourAddress, addressSize + 2);
} }
void SSUSession::ProcessSessionConfirmed (const uint8_t * buf, size_t len) void SSUSession::ProcessSessionConfirmed (const uint8_t * buf, size_t len)
{ {
LogPrint (eLogDebug, "Session confirmed received"); LogPrint (eLogDebug, "SSU: Session confirmed received");
auto headerSize = GetSSUHeaderSize (buf); auto headerSize = GetSSUHeaderSize (buf);
if (headerSize >= len) if (headerSize >= len)
{ {
LogPrint (eLogError, "Session confirmed header size ", len, " exceeds packet length ", len); LogPrint (eLogError, "SSU: Session confirmed header size ", len, " exceeds packet length ", len);
return; return;
} }
const uint8_t * payload = buf + headerSize; const uint8_t * payload = buf + headerSize;
@ -297,7 +297,7 @@ namespace transport
payload += paddingSize; payload += paddingSize;
// verify // verify
if (m_SignedData && !m_SignedData->Verify (m_RemoteIdentity, payload)) if (m_SignedData && !m_SignedData->Verify (m_RemoteIdentity, payload))
LogPrint (eLogError, "Session confirmed SSU signature verification failed"); LogPrint (eLogError, "SSU message 'confirmed' signature verification failed");
m_Data.Send (CreateDeliveryStatusMsg (0)); m_Data.Send (CreateDeliveryStatusMsg (0));
Established (); Established ();
} }
@ -508,7 +508,7 @@ namespace transport
// Charlie's address always v4 // Charlie's address always v4
if (!to.address ().is_v4 ()) if (!to.address ().is_v4 ())
{ {
LogPrint (eLogError, "Charlie's IP must be v4"); LogPrint (eLogError, "SSU: Charlie's IP must be v4");
return; return;
} }
*payload = 4; *payload = 4;
@ -551,7 +551,7 @@ namespace transport
FillHeaderAndEncrypt (PAYLOAD_TYPE_RELAY_RESPONSE, buf, isV4 ? 64 : 80, introKey, iv, introKey); FillHeaderAndEncrypt (PAYLOAD_TYPE_RELAY_RESPONSE, buf, isV4 ? 64 : 80, introKey, iv, introKey);
m_Server.Send (buf, isV4 ? 64 : 80, from); m_Server.Send (buf, isV4 ? 64 : 80, from);
} }
LogPrint (eLogDebug, "SSU relay response sent"); LogPrint (eLogDebug, "SSU: relay response sent");
} }
void SSUSession::SendRelayIntro (std::shared_ptr<SSUSession> session, const boost::asio::ip::udp::endpoint& from) void SSUSession::SendRelayIntro (std::shared_ptr<SSUSession> session, const boost::asio::ip::udp::endpoint& from)
@ -560,7 +560,7 @@ namespace transport
// Alice's address always v4 // Alice's address always v4
if (!from.address ().is_v4 ()) if (!from.address ().is_v4 ())
{ {
LogPrint (eLogError, "Alice's IP must be v4"); LogPrint (eLogError, "SSU: Alice's IP must be v4");
return; return;
} }
uint8_t buf[48 + 18]; uint8_t buf[48 + 18];
@ -576,12 +576,12 @@ namespace transport
RAND_bytes (iv, 16); // random iv RAND_bytes (iv, 16); // random iv
FillHeaderAndEncrypt (PAYLOAD_TYPE_RELAY_INTRO, buf, 48, session->m_SessionKey, iv, session->m_MacKey); FillHeaderAndEncrypt (PAYLOAD_TYPE_RELAY_INTRO, buf, 48, session->m_SessionKey, iv, session->m_MacKey);
m_Server.Send (buf, 48, session->m_RemoteEndpoint); m_Server.Send (buf, 48, session->m_RemoteEndpoint);
LogPrint (eLogDebug, "SSU relay intro sent"); LogPrint (eLogDebug, "SSU: relay intro sent");
} }
void SSUSession::ProcessRelayResponse (const uint8_t * buf, size_t len) void SSUSession::ProcessRelayResponse (const uint8_t * buf, size_t len)
{ {
LogPrint (eLogDebug, "Relay response received"); LogPrint (eLogDebug, "SSU message: Relay response received");
uint8_t remoteSize = *buf; uint8_t remoteSize = *buf;
buf++; // remote size buf++; // remote size
boost::asio::ip::address_v4 remoteIP (bufbe32toh (buf)); boost::asio::ip::address_v4 remoteIP (bufbe32toh (buf));
@ -606,7 +606,7 @@ namespace transport
buf += ourSize; // our address buf += ourSize; // our address
uint16_t ourPort = bufbe16toh (buf); uint16_t ourPort = bufbe16toh (buf);
buf += 2; // our port buf += 2; // our port
LogPrint ("Our external address is ", ourIP.to_string (), ":", ourPort); LogPrint (eLogInfo, "SSU: Our external address is ", ourIP.to_string (), ":", ourPort);
i2p::context.UpdateAddress (ourIP); i2p::context.UpdateAddress (ourIP);
uint32_t nonce = bufbe32toh (buf); uint32_t nonce = bufbe32toh (buf);
buf += 4; // nonce buf += 4; // nonce
@ -619,7 +619,7 @@ namespace transport
{ {
// we didn't have correct endpoint when sent relay request // we didn't have correct endpoint when sent relay request
// now we do // now we do
LogPrint (eLogInfo, "RelayReponse connecting to endpoint ", remoteEndpoint); LogPrint (eLogInfo, "SSU: RelayReponse connecting to endpoint ", remoteEndpoint);
if (i2p::context.GetRouterInfo ().UsesIntroducer ()) // if we are unreachable if (i2p::context.GetRouterInfo ().UsesIntroducer ()) // if we are unreachable
m_Server.Send (buf, 0, remoteEndpoint); // send HolePunch m_Server.Send (buf, 0, remoteEndpoint); // send HolePunch
m_Server.CreateDirectSession (it->second, remoteEndpoint, false); m_Server.CreateDirectSession (it->second, remoteEndpoint, false);
@ -628,7 +628,7 @@ namespace transport
m_RelayRequests.erase (it); m_RelayRequests.erase (it);
} }
else else
LogPrint (eLogError, "Unsolicited RelayResponse, nonce=", nonce); LogPrint (eLogError, "SSU: Unsolicited RelayResponse, nonce=", nonce);
} }
void SSUSession::ProcessRelayIntro (const uint8_t * buf, size_t len) void SSUSession::ProcessRelayIntro (const uint8_t * buf, size_t len)
@ -644,7 +644,7 @@ namespace transport
m_Server.Send (buf, 0, boost::asio::ip::udp::endpoint (address, port)); m_Server.Send (buf, 0, boost::asio::ip::udp::endpoint (address, port));
} }
else else
LogPrint (eLogWarning, "Address size ", size, " is not supported"); LogPrint (eLogWarning, "SSU: Address size ", size, " is not supported");
} }
void SSUSession::FillHeaderAndEncrypt (uint8_t payloadType, uint8_t * buf, size_t len, void SSUSession::FillHeaderAndEncrypt (uint8_t payloadType, uint8_t * buf, size_t len,
@ -652,7 +652,7 @@ namespace transport
{ {
if (len < sizeof (SSUHeader)) if (len < sizeof (SSUHeader))
{ {
LogPrint (eLogError, "Unexpected SSU packet length ", len); LogPrint (eLogError, "SSU: Unexpected packet length ", len);
return; return;
} }
//TODO: we are using a dirty solution here but should work for now //TODO: we are using a dirty solution here but should work for now
@ -676,7 +676,7 @@ namespace transport
{ {
if (len < sizeof (SSUHeader)) if (len < sizeof (SSUHeader))
{ {
LogPrint (eLogError, "Unexpected SSU packet length ", len); LogPrint (eLogError, "SSU: Unexpected packet length ", len);
return; return;
} }
//TODO: we are using a dirty solution here but should work for now //TODO: we are using a dirty solution here but should work for now
@ -698,7 +698,7 @@ namespace transport
{ {
if (len < sizeof (SSUHeader)) if (len < sizeof (SSUHeader))
{ {
LogPrint (eLogError, "Unexpected SSU packet length ", len); LogPrint (eLogError, "SSU: Unexpected packet length ", len);
return; return;
} }
//TODO: since we are accessing a uint8_t this is unlikely to crash due to alignment but should be improved //TODO: since we are accessing a uint8_t this is unlikely to crash due to alignment but should be improved
@ -715,7 +715,7 @@ namespace transport
{ {
if (len < sizeof (SSUHeader)) if (len < sizeof (SSUHeader))
{ {
LogPrint (eLogError, "Unexpected SSU packet length ", len); LogPrint (eLogError, "SSU: Unexpected packet length ", len);
return; return;
} }
//TODO: since we are accessing a uint8_t this is unlikely to crash due to alignment but should be improved //TODO: since we are accessing a uint8_t this is unlikely to crash due to alignment but should be improved
@ -733,7 +733,7 @@ namespace transport
{ {
if (len < sizeof (SSUHeader)) if (len < sizeof (SSUHeader))
{ {
LogPrint (eLogError, "Unexpected SSU packet length ", len); LogPrint (eLogError, "SSU: Unexpected packet length ", len);
return false; return false;
} }
//TODO: since we are accessing a uint8_t this is unlikely to crash due to alignment but should be improved //TODO: since we are accessing a uint8_t this is unlikely to crash due to alignment but should be improved
@ -764,7 +764,7 @@ namespace transport
if (!IsOutgoing ()) // incoming session if (!IsOutgoing ()) // incoming session
ScheduleConnectTimer (); ScheduleConnectTimer ();
else else
LogPrint (eLogError, "SSU wait for connect for outgoing session"); LogPrint (eLogError, "SSU: wait for connect for outgoing session");
} }
void SSUSession::ScheduleConnectTimer () void SSUSession::ScheduleConnectTimer ()
@ -780,7 +780,7 @@ namespace transport
if (!ecode) if (!ecode)
{ {
// timeout expired // timeout expired
LogPrint ("SSU session was not established after ", SSU_CONNECT_TIMEOUT, " second"); LogPrint (eLogWarning, "SSU: session was not established after ", SSU_CONNECT_TIMEOUT, " seconds");
Failed (); Failed ();
} }
} }
@ -858,7 +858,7 @@ namespace transport
{ {
if (ecode != boost::asio::error::operation_aborted) if (ecode != boost::asio::error::operation_aborted)
{ {
LogPrint ("SSU no activity fo ", SSU_TERMINATION_TIMEOUT, " seconds"); LogPrint (eLogInfo, "SSU: no activity for", SSU_TERMINATION_TIMEOUT, " seconds");
Failed (); Failed ();
} }
} }
@ -902,7 +902,7 @@ namespace transport
const uint8_t * introKey = buf + size + 7; const uint8_t * introKey = buf + size + 7;
if (port && !address) if (port && !address)
{ {
LogPrint (eLogWarning, "Address of ", size, " bytes not supported"); LogPrint (eLogWarning, "SSU: Address of ", size, " bytes not supported");
return; return;
} }
switch (m_Server.GetPeerTestParticipant (nonce)) switch (m_Server.GetPeerTestParticipant (nonce))
@ -912,13 +912,13 @@ namespace transport
{ {
if (m_State == eSessionStateEstablished) if (m_State == eSessionStateEstablished)
{ {
LogPrint (eLogDebug, "SSU peer test from Bob. We are Alice"); LogPrint (eLogDebug, "SSU: peer test from Bob. We are Alice");
if (i2p::context.GetStatus () == eRouterStatusTesting) // still not OK if (i2p::context.GetStatus () == eRouterStatusTesting) // still not OK
i2p::context.SetStatus (eRouterStatusFirewalled); i2p::context.SetStatus (eRouterStatusFirewalled);
} }
else else
{ {
LogPrint (eLogDebug, "SSU first peer test from Charlie. We are Alice"); LogPrint (eLogDebug, "SSU: first peer test from Charlie. We are Alice");
i2p::context.SetStatus (eRouterStatusOK); i2p::context.SetStatus (eRouterStatusOK);
m_Server.UpdatePeerTest (nonce, ePeerTestParticipantAlice2); m_Server.UpdatePeerTest (nonce, ePeerTestParticipantAlice2);
SendPeerTest (nonce, senderEndpoint.address ().to_v4 ().to_ulong (), SendPeerTest (nonce, senderEndpoint.address ().to_v4 ().to_ulong (),
@ -929,11 +929,11 @@ namespace transport
case ePeerTestParticipantAlice2: case ePeerTestParticipantAlice2:
{ {
if (m_State == eSessionStateEstablished) if (m_State == eSessionStateEstablished)
LogPrint (eLogDebug, "SSU peer test from Bob. We are Alice"); LogPrint (eLogDebug, "SSU: peer test from Bob. We are Alice");
else else
{ {
// peer test successive // peer test successive
LogPrint (eLogDebug, "SSU second peer test from Charlie. We are Alice"); LogPrint (eLogDebug, "SSU: second peer test from Charlie. We are Alice");
i2p::context.SetStatus (eRouterStatusOK); i2p::context.SetStatus (eRouterStatusOK);
m_Server.RemovePeerTest (nonce); m_Server.RemovePeerTest (nonce);
} }
@ -941,7 +941,7 @@ namespace transport
} }
case ePeerTestParticipantBob: case ePeerTestParticipantBob:
{ {
LogPrint (eLogDebug, "SSU peer test from Charlie. We are Bob"); LogPrint (eLogDebug, "SSU: peer test from Charlie. We are Bob");
auto session = m_Server.GetPeerTestSession (nonce); // session with Alice from PeerTest auto session = m_Server.GetPeerTestSession (nonce); // session with Alice from PeerTest
if (session && session->m_State == eSessionStateEstablished) if (session && session->m_State == eSessionStateEstablished)
session->Send (PAYLOAD_TYPE_PEER_TEST, buf, len); // back to Alice session->Send (PAYLOAD_TYPE_PEER_TEST, buf, len); // back to Alice
@ -950,7 +950,7 @@ namespace transport
} }
case ePeerTestParticipantCharlie: case ePeerTestParticipantCharlie:
{ {
LogPrint (eLogDebug, "SSU peer test from Alice. We are Charlie"); LogPrint (eLogDebug, "SSU: peer test from Alice. We are Charlie");
SendPeerTest (nonce, senderEndpoint.address ().to_v4 ().to_ulong (), SendPeerTest (nonce, senderEndpoint.address ().to_v4 ().to_ulong (),
senderEndpoint.port (), introKey); // to Alice with her actual address senderEndpoint.port (), introKey); // to Alice with her actual address
m_Server.RemovePeerTest (nonce); // nonce has been used m_Server.RemovePeerTest (nonce); // nonce has been used
@ -964,14 +964,14 @@ namespace transport
// new test // new test
if (port) if (port)
{ {
LogPrint (eLogDebug, "SSU peer test from Bob. We are Charlie"); LogPrint (eLogDebug, "SSU: peer test from Bob. We are Charlie");
m_Server.NewPeerTest (nonce, ePeerTestParticipantCharlie); m_Server.NewPeerTest (nonce, ePeerTestParticipantCharlie);
Send (PAYLOAD_TYPE_PEER_TEST, buf, len); // back to Bob Send (PAYLOAD_TYPE_PEER_TEST, buf, len); // back to Bob
SendPeerTest (nonce, be32toh (address), be16toh (port), introKey); // to Alice with her address received from Bob SendPeerTest (nonce, be32toh (address), be16toh (port), introKey); // to Alice with her address received from Bob
} }
else else
{ {
LogPrint (eLogDebug, "SSU peer test from Alice. We are Bob"); LogPrint (eLogDebug, "SSU: peer test from Alice. We are Bob");
auto session = m_Server.GetRandomEstablishedV4Session (shared_from_this ()); // Charlie, TODO: implement v6 support auto session = m_Server.GetRandomEstablishedV4Session (shared_from_this ()); // Charlie, TODO: implement v6 support
if (session) if (session)
{ {
@ -982,7 +982,7 @@ namespace transport
} }
} }
else else
LogPrint (eLogError, "SSU unexpected peer test"); LogPrint (eLogError, "SSU: unexpected peer test");
} }
} }
} }
@ -1045,7 +1045,7 @@ namespace transport
void SSUSession::SendPeerTest () void SSUSession::SendPeerTest ()
{ {
// we are Alice // we are Alice
LogPrint (eLogDebug, "SSU sending peer test"); LogPrint (eLogDebug, "SSU: sending peer test");
auto address = i2p::context.GetRouterInfo ().GetSSUAddress (); auto address = i2p::context.GetRouterInfo ().GetSSUAddress ();
if (!address) if (!address)
{ {
@ -1072,7 +1072,7 @@ namespace transport
// encrypt message with session key // encrypt message with session key
FillHeaderAndEncrypt (PAYLOAD_TYPE_DATA, buf, 48); FillHeaderAndEncrypt (PAYLOAD_TYPE_DATA, buf, 48);
Send (buf, 48); Send (buf, 48);
LogPrint (eLogDebug, "SSU keep-alive sent"); LogPrint (eLogDebug, "SSU: keep-alive sent");
ScheduleTermination (); ScheduleTermination ();
} }
} }
@ -1090,9 +1090,9 @@ namespace transport
} }
catch (std::exception& ex) catch (std::exception& ex)
{ {
LogPrint (eLogError, "SSU send session destoriyed exception ", ex.what ()); LogPrint (eLogError, "SSU: exception while send session destoriyed: ", ex.what ());
} }
LogPrint (eLogDebug, "SSU session destroyed sent"); LogPrint (eLogDebug, "SSU: session destroyed sent");
} }
} }
@ -1104,7 +1104,7 @@ namespace transport
if (paddingSize > 0) msgSize += (16 - paddingSize); if (paddingSize > 0) msgSize += (16 - paddingSize);
if (msgSize > SSU_MTU_V4) if (msgSize > SSU_MTU_V4)
{ {
LogPrint (eLogWarning, "SSU payload size ", msgSize, " exceeds MTU"); LogPrint (eLogWarning, "SSU: payload size ", msgSize, " exceeds MTU");
return; return;
} }
memcpy (buf + sizeof (SSUHeader), payload, len); memcpy (buf + sizeof (SSUHeader), payload, len);

Loading…
Cancel
Save