improve websocket error reporting (#416)

- Add new error `AWS_ERROR_HTTP_WEBSOCKET_PROTOCOL_ERROR`
  - previously, websocket was using `AWS_ERROR_HTTP_PROTOCOL_ERROR`, which makes it look like an HTTP protocol error
- Add logging for errors from websocket encoder & decoder
- Remove some TODOs that have been taken care of

Author: graebm

include/aws/http/http.h

@@ -54,6 +54,7 @@ enum aws_http_errors {
     AWS_ERROR_HTTP_STREAM_MANAGER_SHUTTING_DOWN,
     AWS_ERROR_HTTP_STREAM_MANAGER_CONNECTION_ACQUIRE_FAILURE,
     AWS_ERROR_HTTP_STREAM_MANAGER_UNEXPECTED_HTTP_VERSION,
+    AWS_ERROR_HTTP_WEBSOCKET_PROTOCOL_ERROR,
 
     AWS_ERROR_HTTP_END_RANGE = AWS_ERROR_ENUM_END_RANGE(AWS_C_HTTP_PACKAGE_ID)
 };

source/http.c

@@ -139,6 +139,9 @@ static struct aws_error_info s_errors[] = {
     AWS_DEFINE_ERROR_INFO_HTTP(
         AWS_ERROR_HTTP_STREAM_MANAGER_UNEXPECTED_HTTP_VERSION,
         "Stream acquisition failed because stream manager got an unexpected version of HTTP connection"),
+    AWS_DEFINE_ERROR_INFO_HTTP(
+        AWS_ERROR_HTTP_WEBSOCKET_PROTOCOL_ERROR,
+        "Websocket protocol rules violated by peer"),
 };
 /* clang-format on */
 

source/websocket.c

@@ -24,17 +24,8 @@
 
 /* TODO: echo payload of peer CLOSE */
 
-/* TODO: Can we be sure socket will always mark aws_io_messages as complete? */
-
 /* TODO: If something goes wrong during normal shutdown, do I change the error_code? */
 
-/* TODO: Delayed payload works by sending 0-size io_msgs down pipe and trying again when they're compele.
- *       Do something more efficient? */
-
-/* TODO: don't fire send completion until data written to socket .. which also means delaying on_shutdown cb */
-
-/* TODO: stop using the HTTP_PARSE error, give websocket its own error */
-
 struct outgoing_frame {
     struct aws_websocket_send_frame_options def;
     struct aws_linked_list_node node;
@@ -249,8 +240,6 @@ static void s_unlock_synced_data(struct aws_websocket *websocket) {
 }
 
 struct aws_websocket *aws_websocket_handler_new(const struct aws_websocket_handler_options *options) {
-    /* TODO: validate options */
-
     struct aws_channel_slot *slot = NULL;
     struct aws_websocket *websocket = NULL;
     int err;
@@ -722,8 +711,7 @@ static void s_try_write_outgoing_frames(struct aws_websocket *websocket) {
         return;
     }
 
-    /* Prepare to send aws_io_message up the channel.
-     * Note that the write-completion callback may fire before send_message() returns */
+    /* Prepare to send aws_io_message up the channel. */
 
     /* If CLOSE frame was written, that's the last data we'll write */
     if (wrote_close_frame) {
@@ -863,7 +851,6 @@ static int s_handler_process_write_message(
 
     int err = s_send_frame(websocket, &options, false);
     if (err) {
-        /* TODO: mqtt handler needs to clean up messsages that fail to send. */
         return AWS_OP_ERR;
     }
 

source/websocket_decoder.c

@@ -5,7 +5,7 @@
 
 #include <aws/http/private/websocket_decoder.h>
 
-/* TODO: decoder logging */
+#include <inttypes.h>
 
 typedef int(state_fn)(struct aws_websocket_decoder *decoder, struct aws_byte_cursor *data);
 
@@ -46,7 +46,12 @@ static int s_state_opcode_byte(struct aws_websocket_decoder *decoder, struct aws
         case AWS_WEBSOCKET_OPCODE_PONG:
             break;
         default:
-            return aws_raise_error(AWS_ERROR_HTTP_PROTOCOL_ERROR);
+            AWS_LOGF_ERROR(
+                AWS_LS_HTTP_WEBSOCKET,
+                "id=%p: Received frame with unknown opcode 0x%" PRIx8,
+                (void *)decoder->user_data,
+                decoder->current_frame.opcode);
+            return aws_raise_error(AWS_ERROR_HTTP_WEBSOCKET_PROTOCOL_ERROR);
     }
 
     /* RFC-6455 Section 5.2 Fragmentation
@@ -61,15 +66,23 @@ static int s_state_opcode_byte(struct aws_websocket_decoder *decoder, struct aws
         bool is_continuation_frame = AWS_WEBSOCKET_OPCODE_CONTINUATION == decoder->current_frame.opcode;
 
         if (decoder->expecting_continuation_data_frame != is_continuation_frame) {
-            return aws_raise_error(AWS_ERROR_HTTP_PROTOCOL_ERROR);
+            AWS_LOGF_ERROR(
+                AWS_LS_HTTP_WEBSOCKET,
+                "id=%p: Fragmentation error. Received start of new message before end of previous message",
+                (void *)decoder->user_data);
+            return aws_raise_error(AWS_ERROR_HTTP_WEBSOCKET_PROTOCOL_ERROR);
         }
 
         decoder->expecting_continuation_data_frame = !decoder->current_frame.fin;
 
     } else {
         /* Control frames themselves MUST NOT be fragmented. */
         if (!decoder->current_frame.fin) {
-            return aws_raise_error(AWS_ERROR_HTTP_PROTOCOL_ERROR);
+            AWS_LOGF_ERROR(
+                AWS_LS_HTTP_WEBSOCKET,
+                "id=%p: Received fragmented control frame. This is illegal",
+                (void *)decoder->user_data);
+            return aws_raise_error(AWS_ERROR_HTTP_WEBSOCKET_PROTOCOL_ERROR);
         }
     }
 
@@ -150,21 +163,17 @@ static int s_state_extended_length(struct aws_websocket_decoder *decoder, struct
     struct aws_byte_cursor cache_cursor = aws_byte_cursor_from_array(decoder->state_cache, total_bytes_extended_length);
     if (total_bytes_extended_length == 2) {
         uint16_t val;
-        if (!aws_byte_cursor_read_be16(&cache_cursor, &val)) {
-            return aws_raise_error(AWS_ERROR_HTTP_PROTOCOL_ERROR);
-        }
-
+        aws_byte_cursor_read_be16(&cache_cursor, &val);
         decoder->current_frame.payload_length = val;
     } else {
-        if (!aws_byte_cursor_read_be64(&cache_cursor, &decoder->current_frame.payload_length)) {
-            return aws_raise_error(AWS_ERROR_HTTP_PROTOCOL_ERROR);
-        }
+        aws_byte_cursor_read_be64(&cache_cursor, &decoder->current_frame.payload_length);
     }
 
     if (decoder->current_frame.payload_length < min_acceptable_value ||
         decoder->current_frame.payload_length > max_acceptable_value) {
 
-        return aws_raise_error(AWS_ERROR_HTTP_PROTOCOL_ERROR);
+        AWS_LOGF_ERROR(AWS_LS_HTTP_WEBSOCKET, "id=%p: Failed to decode payload length", (void *)decoder->user_data);
+        return aws_raise_error(AWS_ERROR_HTTP_WEBSOCKET_PROTOCOL_ERROR);
     }
 
     decoder->state = AWS_WEBSOCKET_DECODER_STATE_MASKING_KEY_CHECK;

source/websocket_encoder.c

@@ -5,9 +5,7 @@
 
 #include <aws/http/private/websocket_encoder.h>
 
-/* TODO: encoder logging */
-/* TODO: implement masking function in aws-c-common */
-/* TODO: use nospec advance? */
+#include <inttypes.h>
 
 typedef int(state_fn)(struct aws_websocket_encoder *encoder, struct aws_byte_buf *out_buf);
 
@@ -219,6 +217,11 @@ static int s_state_payload(struct aws_websocket_encoder *encoder, struct aws_byt
     } else {
         /* Some more error-checking... */
         if (encoder->state_bytes_processed > encoder->frame.payload_length) {
+            AWS_LOGF_ERROR(
+                AWS_LS_HTTP_WEBSOCKET,
+                "id=%p: Outgoing stream has exceeded stated payload length of %" PRIu64,
+                (void *)encoder->user_data,
+                encoder->frame.payload_length);
             return aws_raise_error(AWS_ERROR_HTTP_OUTGOING_STREAM_LENGTH_INCORRECT);
         }
     }
@@ -276,11 +279,20 @@ int aws_websocket_encoder_start_frame(struct aws_websocket_encoder *encoder, con
 
     /* Opcode must fit in 4bits */
     if (frame->opcode != (frame->opcode & 0x0F)) {
+        AWS_LOGF_ERROR(
+            AWS_LS_HTTP_WEBSOCKET,
+            "id=%p: Outgoing frame has unknown opcode 0x%" PRIx8,
+            (void *)encoder->user_data,
+            frame->opcode);
         return aws_raise_error(AWS_ERROR_INVALID_ARGUMENT);
     }
 
     /* High bit of 8byte length must be clear */
     if (frame->payload_length > AWS_WEBSOCKET_8BYTE_EXTENDED_LENGTH_MAX_VALUE) {
+        AWS_LOGF_ERROR(
+            AWS_LS_HTTP_WEBSOCKET,
+            "id=%p: Outgoing frame's payload length exceeds the max",
+            (void *)encoder->user_data);
         return aws_raise_error(AWS_ERROR_INVALID_ARGUMENT);
     }
 
@@ -294,13 +306,22 @@ int aws_websocket_encoder_start_frame(struct aws_websocket_encoder *encoder, con
         bool is_continuation_frame = (AWS_WEBSOCKET_OPCODE_CONTINUATION == frame->opcode);
 
         if (encoder->expecting_continuation_data_frame != is_continuation_frame) {
+            AWS_LOGF_ERROR(
+                AWS_LS_HTTP_WEBSOCKET,
+                "id=%p: Fragmentation error. Outgoing frame starts a new message but previous message has not ended",
+                (void *)encoder->user_data);
             return aws_raise_error(AWS_ERROR_INVALID_STATE);
         }
 
         keep_expecting_continuation_data_frame = !frame->fin;
     } else {
         /* Control frames themselves MUST NOT be fragmented. */
         if (!frame->fin) {
+            AWS_LOGF_ERROR(
+                AWS_LS_HTTP_WEBSOCKET,
+                "id=%p: It is illegal to send a fragmented control frame",
+                (void *)encoder->user_data);
+
             return aws_raise_error(AWS_ERROR_INVALID_ARGUMENT);
         }
     }

tests/test_websocket_decoder.c

@@ -377,7 +377,7 @@ DECODER_TEST_CASE(websocket_decoder_extended_length_2byte) {
             aws_raise_error(-1); /* overwrite last-error */
 
             ASSERT_FAILS(aws_websocket_decoder_process(&tester.decoder, &input_cursor, &frame_complete));
-            ASSERT_INT_EQUALS(AWS_ERROR_HTTP_PROTOCOL_ERROR, aws_last_error());
+            ASSERT_INT_EQUALS(AWS_ERROR_HTTP_WEBSOCKET_PROTOCOL_ERROR, aws_last_error());
         }
     }
 
@@ -448,7 +448,7 @@ DECODER_TEST_CASE(websocket_decoder_extended_length_8byte) {
             aws_raise_error(-1); /* overwrite last-error */
 
             ASSERT_FAILS(aws_websocket_decoder_process(&tester.decoder, &input_cursor, &frame_complete));
-            ASSERT_INT_EQUALS(AWS_ERROR_HTTP_PROTOCOL_ERROR, aws_last_error());
+            ASSERT_INT_EQUALS(AWS_ERROR_HTTP_WEBSOCKET_PROTOCOL_ERROR, aws_last_error());
         }
     }
 
@@ -530,7 +530,7 @@ DECODER_TEST_CASE(websocket_decoder_fail_on_unknown_opcode) {
     bool frame_complete;
     struct aws_byte_cursor input_cursor = aws_byte_cursor_from_array(input, sizeof(input));
     ASSERT_FAILS(aws_websocket_decoder_process(&tester.decoder, &input_cursor, &frame_complete));
-    ASSERT_INT_EQUALS(AWS_ERROR_HTTP_PROTOCOL_ERROR, aws_last_error());
+    ASSERT_INT_EQUALS(AWS_ERROR_HTTP_WEBSOCKET_PROTOCOL_ERROR, aws_last_error());
 
     ASSERT_SUCCESS(s_decoder_tester_clean_up(&tester));
     return AWS_OP_SUCCESS;
@@ -626,7 +626,7 @@ DECODER_TEST_CASE(websocket_decoder_fail_on_bad_fragmentation) {
     struct aws_byte_cursor input_cursor = aws_byte_cursor_from_array(input, sizeof(input));
     ASSERT_SUCCESS(aws_websocket_decoder_process(&tester.decoder, &input_cursor, &frame_complete));
     ASSERT_FAILS(aws_websocket_decoder_process(&tester.decoder, &input_cursor, &frame_complete));
-    ASSERT_INT_EQUALS(AWS_ERROR_HTTP_PROTOCOL_ERROR, aws_last_error());
+    ASSERT_INT_EQUALS(AWS_ERROR_HTTP_WEBSOCKET_PROTOCOL_ERROR, aws_last_error());
 
     ASSERT_SUCCESS(s_decoder_tester_clean_up(&tester));
     return AWS_OP_SUCCESS;
@@ -646,7 +646,7 @@ DECODER_TEST_CASE(websocket_decoder_control_frame_cannot_be_fragmented) {
     bool frame_complete;
     struct aws_byte_cursor input_cursor = aws_byte_cursor_from_array(input, sizeof(input));
     ASSERT_FAILS(aws_websocket_decoder_process(&tester.decoder, &input_cursor, &frame_complete));
-    ASSERT_INT_EQUALS(AWS_ERROR_HTTP_PROTOCOL_ERROR, aws_last_error());
+    ASSERT_INT_EQUALS(AWS_ERROR_HTTP_WEBSOCKET_PROTOCOL_ERROR, aws_last_error());
 
     ASSERT_SUCCESS(s_decoder_tester_clean_up(&tester));
     return AWS_OP_SUCCESS;