Add more logging to Ctrl, for #36

This commit is contained in:
Florian Märkl 2019-10-05 12:30:36 +02:00
commit 8779d7612a
No known key found for this signature in database
GPG key ID: 125BC8A5A6A1E857
5 changed files with 74 additions and 9 deletions

View file

@ -24,6 +24,8 @@
#define CHIAKI_SOCKET_IS_INVALID(s) ((s) == INVALID_SOCKET)
#define CHIAKI_INVALID_SOCKET INVALID_SOCKET
#define CHIAKI_SOCKET_CLOSE(s) closesocket(s)
#define CHIAKI_SOCKET_ERROR_FMT "%d"
#define CHIAKI_SOCKET_ERROR_VALUE (WSAGetLastError())
#ifndef WIN32_LEAN_AND_MEAN
#define WIN32_LEAN_AND_MEAN
#endif
@ -33,6 +35,8 @@
#define CHIAKI_SOCKET_IS_INVALID(s) ((s) < 0)
#define CHIAKI_INVALID_SOCKET (-1)
#define CHIAKI_SOCKET_CLOSE(s) close(s)
#define CHIAKI_SOCKET_ERROR_FMT "%s"
#define CHIAKI_SOCKET_ERROR_VALUE (strerror(errno))
#endif
#ifdef __cplusplus

View file

@ -91,6 +91,7 @@ typedef enum {
CHIAKI_QUIT_REASON_SESSION_REQUEST_RP_IN_USE,
CHIAKI_QUIT_REASON_SESSION_REQUEST_RP_CRASH,
CHIAKI_QUIT_REASON_CTRL_UNKNOWN,
CHIAKI_QUIT_REASON_CTRL_CONNECT_FAILED,
CHIAKI_QUIT_REASON_CTRL_CONNECTION_REFUSED,
CHIAKI_QUIT_REASON_STREAM_CONNECTION_UNKNOWN,
CHIAKI_QUIT_REASON_STREAM_CONNECTION_REMOTE_DISCONNECTED

View file

@ -154,7 +154,7 @@ static void *ctrl_thread_func(void *user)
ChiakiErrorCode err = ctrl_connect(ctrl);
if(err != CHIAKI_ERR_SUCCESS)
{
ctrl_failed(ctrl, CHIAKI_QUIT_REASON_CTRL_UNKNOWN);
ctrl_failed(ctrl, CHIAKI_QUIT_REASON_CTRL_CONNECT_FAILED);
return NULL;
}
@ -233,7 +233,10 @@ static void *ctrl_thread_func(void *user)
if(received <= 0)
{
if(received < 0)
{
CHIAKI_LOGE(ctrl->session->log, "Ctrl failed to recv: " CHIAKI_SOCKET_ERROR_FMT, CHIAKI_SOCKET_ERROR_VALUE);
ctrl_failed(ctrl, CHIAKI_QUIT_REASON_CTRL_UNKNOWN);
}
break;
}
@ -304,6 +307,10 @@ static void ctrl_message_received(ChiakiCtrl *ctrl, uint16_t msg_type, uint8_t *
}
}
CHIAKI_LOGV(ctrl->session->log, "Ctrl received message of type %#x, size %#llx", (unsigned int)msg_type, (unsigned long long)payload_size);
if(payload_size > 0)
chiaki_log_hexdump(ctrl->session->log, CHIAKI_LOG_VERBOSE, payload, payload_size);
switch(msg_type)
{
case CTRL_MESSAGE_TYPE_SESSION_ID:
@ -409,7 +416,7 @@ static void ctrl_message_received_login(ChiakiCtrl *ctrl, uint8_t *payload, size
{
if(payload_size != 1)
{
CHIAKI_LOGW(ctrl->session->log, "Ctrl received Login message with payload of size %llx", (unsigned long long)payload_size);
CHIAKI_LOGW(ctrl->session->log, "Ctrl received Login message with payload of size %#llx", (unsigned long long)payload_size);
if(payload_size < 1)
return;
}
@ -436,7 +443,7 @@ static void ctrl_message_received_login(ChiakiCtrl *ctrl, uint8_t *payload, size
CHIAKI_LOGW(ctrl->session->log, "Ctrl Login PIN incorrect message, but PIN was not requested");
break;
default:
CHIAKI_LOGI(ctrl->session->log, "Ctrl received Login message with state: %x", state);
CHIAKI_LOGI(ctrl->session->log, "Ctrl received Login message with state: %#x", state);
break;
}
}
@ -480,7 +487,10 @@ static ChiakiErrorCode ctrl_connect(ChiakiCtrl *ctrl)
struct addrinfo *addr = session->connect_info.host_addrinfo_selected;
struct sockaddr *sa = malloc(addr->ai_addrlen);
if(!sa)
{
CHIAKI_LOGE(session->log, "Ctrl failed to alloc sockaddr");
return CHIAKI_ERR_MEMORY;
}
memcpy(sa, addr->ai_addr, addr->ai_addrlen);
if(sa->sa_family == AF_INET)
@ -488,10 +498,13 @@ static ChiakiErrorCode ctrl_connect(ChiakiCtrl *ctrl)
else if(sa->sa_family == AF_INET6)
((struct sockaddr_in6 *)sa)->sin6_port = htons(SESSION_CTRL_PORT);
else
{
CHIAKI_LOGE(session->log, "Ctrl got invalid sockaddr");
return CHIAKI_ERR_INVALID_DATA;
}
chiaki_socket_t sock = socket(sa->sa_family, SOCK_STREAM, IPPROTO_TCP);
if(sock < 0)
if(CHIAKI_SOCKET_IS_INVALID(sock))
{
CHIAKI_LOGE(session->log, "Session ctrl socket creation failed.");
ctrl_failed(ctrl, CHIAKI_QUIT_REASON_CTRL_UNKNOWN);
@ -502,9 +515,16 @@ static ChiakiErrorCode ctrl_connect(ChiakiCtrl *ctrl)
free(sa);
if(r < 0)
{
#ifdef _WIN32
int errsv = WSAGetLastError();
CHIAKI_LOGE(session->log, "Ctrl connect failed: %d", errsv);
ChiakiQuitReason quit_reason = errsv == WSAECONNREFUSED ? CHIAKI_QUIT_REASON_CTRL_CONNECTION_REFUSED : CHIAKI_QUIT_REASON_CTRL_UNKNOWN;
#else
int errsv = errno;
CHIAKI_LOGE(session->log, "Ctrl connect failed: %s", strerror(errsv));
ctrl_failed(ctrl, errsv == ECONNREFUSED ? CHIAKI_QUIT_REASON_CTRL_CONNECTION_REFUSED : CHIAKI_QUIT_REASON_CTRL_UNKNOWN);
ChiakiQuitReason quit_reason = errsv == ECONNREFUSED ? CHIAKI_QUIT_REASON_CTRL_CONNECTION_REFUSED : CHIAKI_QUIT_REASON_CTRL_UNKNOWN;
#endif
ctrl_failed(ctrl, quit_reason);
CHIAKI_SOCKET_CLOSE(sock);
return CHIAKI_ERR_NETWORK;
}
@ -578,10 +598,34 @@ static ChiakiErrorCode ctrl_connect(ChiakiCtrl *ctrl)
if(err != CHIAKI_ERR_SUCCESS)
{
if(err != CHIAKI_ERR_CANCELED)
{
#ifdef _WIN32
int errsv = WSAGetLastError;
#else
int errsv = errno;
#endif
CHIAKI_LOGE(session->log, "Failed to receive ctrl request response: %s", chiaki_error_string(err));
if(err == CHIAKI_ERR_NETWORK)
{
CHIAKI_LOGE(session->log, "Ctrl request response network error: " CHIAKI_SOCKET_ERROR_FMT,
#ifdef _WIN32
errsv
#else
strerror(errsv)
#endif
);
}
}
else
{
CHIAKI_LOGI(session->log, "Ctrl canceled while receiving ctrl request response");
}
goto error;
}
CHIAKI_LOGI(session->log, "Ctrl received http header as response");
chiaki_log_hexdump(session->log, CHIAKI_LOG_VERBOSE, (const uint8_t *)buf, header_size);
ChiakiHttpResponse http_response;
err = chiaki_http_response_parse(&http_response, buf, header_size);
if(err != CHIAKI_ERR_SUCCESS)
@ -590,15 +634,18 @@ static ChiakiErrorCode ctrl_connect(ChiakiCtrl *ctrl)
goto error;
}
CHIAKI_LOGI(session->log, "Ctrl received ctrl request http response");
CtrlResponse response;
parse_ctrl_response(&response, &http_response);
chiaki_http_response_fini(&http_response);
if(!response.success)
{
CHIAKI_LOGE(session->log, "Ctrl http response was not successful. HTTP code was %d", http_response.code);
chiaki_http_response_fini(&http_response);
err = CHIAKI_ERR_UNKNOWN;
goto error;
}
chiaki_http_response_fini(&http_response);
if(response.server_type_valid)
{
@ -607,7 +654,11 @@ static ChiakiErrorCode ctrl_connect(ChiakiCtrl *ctrl)
response.rp_server_type,
response.rp_server_type,
sizeof(response.rp_server_type));
response.server_type_valid = err2 == CHIAKI_ERR_SUCCESS;
if(err2 != CHIAKI_ERR_SUCCESS)
{
CHIAKI_LOGE(session->log, "Ctrl failed to decrypt RP-Server-Type");
response.server_type_valid = false;
}
}
if(!response.server_type_valid)

View file

@ -164,7 +164,7 @@ CHIAKI_EXPORT ChiakiErrorCode chiaki_recv_http_header(int sock, char *buf, size_
int received = (int)recv(sock, buf, (int)buf_size, 0);
if(received <= 0)
return CHIAKI_ERR_NETWORK;
return received == 0 ? CHIAKI_ERR_DISCONNECTED : CHIAKI_ERR_NETWORK;
*received_size += received;
for(; received > 0; buf++, received--)

View file

@ -126,6 +126,8 @@ CHIAKI_EXPORT const char *chiaki_quit_reason_string(ChiakiQuitReason reason)
return "Unknown Ctrl Error";
case CHIAKI_QUIT_REASON_CTRL_CONNECTION_REFUSED:
return "Connection Refused in Ctrl";
case CHIAKI_QUIT_REASON_CTRL_CONNECT_FAILED:
return "Ctrl failed to connect";
case CHIAKI_QUIT_REASON_STREAM_CONNECTION_UNKNOWN:
return "Unknown Error in Stream Connection";
case CHIAKI_QUIT_REASON_STREAM_CONNECTION_REMOTE_DISCONNECTED:
@ -363,7 +365,10 @@ static void *session_thread_func(void *arg)
CHECK_STOP(quit_ctrl);
if(session->ctrl_failed)
{
CHIAKI_LOGE(session->log, "Ctrl has failed while waiting for ctrl startup");
goto ctrl_failed;
}
bool pin_incorrect = false;
while(session->ctrl_login_pin_requested)
@ -382,7 +387,10 @@ static void *session_thread_func(void *arg)
chiaki_cond_timedwait_pred(&session->state_cond, &session->state_mutex, UINT64_MAX, session_check_state_pred_pin, session);
CHECK_STOP(quit_ctrl);
if(session->ctrl_failed)
{
CHIAKI_LOGE(session->log, "Ctrl has failed while waiting for PIN entry");
goto ctrl_failed;
}
assert(session->login_pin_entered && session->login_pin);
CHIAKI_LOGI(session->log, "Session received entered Login PIN, forwarding to Ctrl");
@ -399,6 +407,7 @@ static void *session_thread_func(void *arg)
if(!session->ctrl_session_id_received)
{
CHIAKI_LOGE(session->log, "Ctrl did not receive session id");
ctrl_failed:
CHIAKI_LOGE(session->log, "Ctrl has failed, shutting down");
if(session->quit_reason == CHIAKI_QUIT_REASON_NONE)