io: add trace events for websockets frame handling

It is useful to trace websockets frame encoding/decoding when debugging
problems.

Reviewed-by: Stefan Hajnoczi <stefanha@redhat.com>
Signed-off-by: Daniel P. Berrange <berrange@redhat.com>

io/channel-websock.c

@@ -582,7 +582,8 @@ static gboolean qio_channel_websock_handshake_io(QIOChannel *ioc,
 }
 
 
-static void qio_channel_websock_encode_buffer(Buffer *output,
+static void qio_channel_websock_encode_buffer(QIOChannelWebsock *ioc,
+                                              Buffer *output,
                                               uint8_t opcode, Buffer *buffer)
 {
     size_t header_size;
@@ -608,6 +609,7 @@ static void qio_channel_websock_encode_buffer(Buffer *output,
     }
     header_size -= QIO_CHANNEL_WEBSOCK_HEADER_LEN_MASK;
 
+    trace_qio_channel_websock_encode(ioc, opcode, header_size, buffer->offset);
     buffer_reserve(output, header_size + buffer->offset);
     buffer_append(output, header.buf, header_size);
     buffer_append(output, buffer->buffer, buffer->offset);
@@ -620,7 +622,7 @@ static void qio_channel_websock_encode(QIOChannelWebsock *ioc)
         return;
     }
     qio_channel_websock_encode_buffer(
-        &ioc->encoutput, QIO_CHANNEL_WEBSOCK_OPCODE_BINARY_FRAME,
+        ioc, &ioc->encoutput, QIO_CHANNEL_WEBSOCK_OPCODE_BINARY_FRAME,
         &ioc->rawoutput);
     buffer_reset(&ioc->rawoutput);
 }
@@ -640,7 +642,8 @@ static void qio_channel_websock_write_close(QIOChannelWebsock *ioc,
         buffer_append(&ioc->rawoutput, reason, strlen(reason));
     }
     qio_channel_websock_encode_buffer(
-        &ioc->encoutput, QIO_CHANNEL_WEBSOCK_OPCODE_CLOSE, &ioc->rawoutput);
+        ioc, &ioc->encoutput, QIO_CHANNEL_WEBSOCK_OPCODE_CLOSE,
+        &ioc->rawoutput);
     buffer_reset(&ioc->rawoutput);
     qio_channel_websock_write_wire(ioc, NULL);
     qio_channel_shutdown(ioc->master, QIO_CHANNEL_SHUTDOWN_BOTH, NULL);
@@ -682,6 +685,9 @@ static int qio_channel_websock_decode_header(QIOChannelWebsock *ioc,
         opcode = ioc->opcode;
     }
 
+    trace_qio_channel_websock_header_partial_decode(ioc, payload_len,
+                                                    fin, opcode, (int)has_mask);
+
     if (opcode == QIO_CHANNEL_WEBSOCK_OPCODE_CLOSE) {
         /* disconnect */
         return 0;
@@ -746,6 +752,8 @@ static int qio_channel_websock_decode_header(QIOChannelWebsock *ioc,
         return QIO_CHANNEL_ERR_BLOCK;
     }
 
+    trace_qio_channel_websock_header_full_decode(
+        ioc, header_size, ioc->payload_remain, ioc->mask.u);
     buffer_advance(&ioc->encinput, header_size);
     return 0;
 }
@@ -791,6 +799,9 @@ static int qio_channel_websock_decode_payload(QIOChannelWebsock *ioc,
         }
     }
 
+    trace_qio_channel_websock_payload_decode(
+        ioc, ioc->opcode, ioc->payload_remain);
+
     if (ioc->opcode == QIO_CHANNEL_WEBSOCK_OPCODE_BINARY_FRAME) {
         if (payload_len) {
             /* binary frames are passed on */
@@ -803,7 +814,7 @@ static int qio_channel_websock_decode_payload(QIOChannelWebsock *ioc,
         if (payload_len) {
             /* echo client status */
             qio_channel_websock_encode_buffer(
-                &ioc->encoutput, QIO_CHANNEL_WEBSOCK_OPCODE_CLOSE,
+                ioc, &ioc->encoutput, QIO_CHANNEL_WEBSOCK_OPCODE_CLOSE,
                 &ioc->encinput);
             qio_channel_websock_write_wire(ioc, NULL);
             qio_channel_shutdown(ioc->master, QIO_CHANNEL_SHUTDOWN_BOTH, NULL);
@@ -817,7 +828,8 @@ static int qio_channel_websock_decode_payload(QIOChannelWebsock *ioc,
         /* ping frames produce an immediate reply */
         buffer_reset(&ioc->ping_reply);
         qio_channel_websock_encode_buffer(
-            &ioc->ping_reply, QIO_CHANNEL_WEBSOCK_OPCODE_PONG, &ioc->encinput);
+            ioc, &ioc->ping_reply, QIO_CHANNEL_WEBSOCK_OPCODE_PONG,
+            &ioc->encinput);
     }   /* pong frames are ignored */
 
     if (payload_len) {
@@ -1176,6 +1188,7 @@ static int qio_channel_websock_close(QIOChannel *ioc,
 {
     QIOChannelWebsock *wioc = QIO_CHANNEL_WEBSOCK(ioc);
 
+    trace_qio_channel_websock_close(ioc);
     return qio_channel_close(wioc->master, errp);
 }
 

io/trace-events

@@ -48,6 +48,11 @@ qio_channel_websock_handshake_pending(void *ioc, int status) "Websock handshake
 qio_channel_websock_handshake_reply(void *ioc) "Websock handshake reply ioc=%p"
 qio_channel_websock_handshake_fail(void *ioc, const char *msg) "Websock handshake fail ioc=%p err=%s"
 qio_channel_websock_handshake_complete(void *ioc) "Websock handshake complete ioc=%p"
+qio_channel_websock_header_partial_decode(void *ioc, size_t payloadlen, unsigned char fin, unsigned char opcode, unsigned char has_mask) "Websocket header decoded ioc=%p payload-len=%zu fin=0x%x opcode=0x%x has_mask=0x%x"
+qio_channel_websock_header_full_decode(void *ioc, size_t headerlen, size_t payloadlen, uint32_t mask) "Websocket header decoded ioc=%p header-len=%zu payload-len=%zu mask=0x%x"
+qio_channel_websock_payload_decode(void *ioc, uint8_t opcode, size_t payload_remain) "Websocket header decoded ioc=%p opcode=0x%x payload-remain=%zu"
+qio_channel_websock_encode(void *ioc, uint8_t opcode, size_t payloadlen, size_t headerlen) "Websocket encoded ioc=%p opcode=0x%x header-len=%zu payload-len=%zu"
+qio_channel_websock_close(void *ioc) "Websocket close ioc=%p"
 
 # io/channel-command.c
 qio_channel_command_new_pid(void *ioc, int writefd, int readfd, int pid) "Command new pid ioc=%p writefd=%d readfd=%d pid=%d"