Skip to content

Commit 91bc019

Browse files
mathieucarboumathieucarbou
committed
Review logging across WebSocket implementation
1 parent 04991a7 commit 91bc019

1 file changed

Lines changed: 49 additions & 36 deletions

File tree

‎src/AsyncWebSocket.cpp‎

Lines changed: 49 additions & 36 deletions
Original file line numberDiff line numberDiff line change
@@ -171,8 +171,9 @@ size_t AsyncWebSocketMessage::ack(size_t len, uint32_t time) {
171171
if (_sent >= _WSbuffer->size() && _acked >= _ack) {
172172
_status = WS_MSG_SENT;
173173
}
174-
async_ws_log_v("opcode: %" PRIu8 ", acked: %u/%u, left: %u/%u, status: %d", _opcode, _acked, _ack, len - pending, len, static_cast<int>(_status));
175-
return len - pending;
174+
const size_t remaining = len - pending;
175+
async_ws_log_v("ACK[%" PRIu8 "] ack: %u/%u => %d", _opcode, _acked, _ack, remaining, len, static_cast<int>(_status));
176+
return remaining;
176177
}
177178

178179
size_t AsyncWebSocketMessage::send(AsyncClient *client) {
@@ -182,20 +183,22 @@ size_t AsyncWebSocketMessage::send(AsyncClient *client) {
182183
}
183184

184185
if (_status != WS_MSG_SENDING) {
185-
async_ws_log_v("C[%" PRIu16 "] Wrong status: got: %d, expected: %d", client->remotePort(), static_cast<int>(_status), static_cast<int>(WS_MSG_SENDING));
186+
async_ws_log_v("SEND[%" PRIu8 "] => [%" PRIu16 "] WS_MSG_SENDING != %d", _opcode, client->remotePort(), static_cast<int>(_status));
186187
return 0;
187188
}
188189

189190
if (_sent == _WSbuffer->size()) {
190191
if (_acked == _ack) {
191192
_status = WS_MSG_SENT;
192193
}
193-
async_ws_log_v("C[%" PRIu16 "] Already sent: %u/%u", client->remotePort(), _sent, _WSbuffer->size());
194+
async_ws_log_v("SEND[%" PRIu8 "] => [%" PRIu16 "] WS_MSG_SENT %u/%u (acked: %u/%u)", _opcode, client->remotePort(), _sent, _WSbuffer->size(), _acked, _ack);
194195
return 0;
195196
}
196197
if (_sent > _WSbuffer->size()) {
197198
_status = WS_MSG_ERROR;
198-
async_ws_log_v("C[%" PRIu16 "] Error, sent more: %u/%u", client->remotePort(), _sent, _WSbuffer->size());
199+
async_ws_log_v(
200+
"SEND[%" PRIu8 "] => [%" PRIu16 "] WS_MSG_ERROR %u/%u (acked: %u/%u)", _opcode, client->remotePort(), _sent, _WSbuffer->size(), _acked, _ack
201+
);
199202
return 0;
200203
}
201204

@@ -204,7 +207,7 @@ size_t AsyncWebSocketMessage::send(AsyncClient *client) {
204207

205208
// not enough space in lwip buffer ?
206209
if (!window) {
207-
async_ws_log_v("C[%" PRIu16 "] No space left to send more data: acked: %u, sent: %u, remaining: %u", client->remotePort(), _acked, _sent, toSend);
210+
async_ws_log_v("SEND[%" PRIu8 "] => [%" PRIu16 "] NO_SPACE %u", _opcode, client->remotePort(), toSend);
208211
return 0;
209212
}
210213

@@ -224,7 +227,9 @@ size_t AsyncWebSocketMessage::send(AsyncClient *client) {
224227
_ack -= (toSend - sent);
225228
}
226229

227-
async_ws_log_v("C[%" PRIu16 "] sent: %u/%u, final: %d, acked: %u/%u", client->remotePort(), _sent, _WSbuffer->size(), final, _acked, _ack);
230+
async_ws_log_v(
231+
"SEND[%" PRIu8 "] => [%" PRIu16 "] WS_MSG_SENDING %u/%u (acked: %u/%u)", _opcode, client->remotePort(), _sent, _WSbuffer->size(), _acked, _ack
232+
);
228233
return sent;
229234
}
230235

@@ -304,6 +309,8 @@ void AsyncWebSocketClient::_clearQueue() {
304309
void AsyncWebSocketClient::_onAck(size_t len, uint32_t time) {
305310
_lastMessageTime = millis();
306311

312+
async_ws_log_v("[%s][%" PRIu32 "] START ACK(%" PRIu32 ", %" PRIu32 ") Q:%" PRIu32, _server->url(), _clientId, len, time, _messageQueue.size());
313+
307314
#ifdef ESP32
308315
std::unique_lock<std::recursive_mutex> lock(_lock);
309316
#endif
@@ -315,6 +322,7 @@ void AsyncWebSocketClient::_onAck(size_t len, uint32_t time) {
315322
if (_status == WS_DISCONNECTING && head.opcode() == WS_DISCONNECT) {
316323
_controlQueue.pop_front();
317324
_status = WS_DISCONNECTED;
325+
async_ws_log_v("[%s][%" PRIu32 "] ACK WS_DISCONNECTED", _server->url(), _clientId);
318326
if (_client) {
319327
#ifdef ESP32
320328
/*
@@ -343,6 +351,8 @@ void AsyncWebSocketClient::_onAck(size_t len, uint32_t time) {
343351

344352
_clearQueue();
345353

354+
async_ws_log_v("[%s][%" PRIu32 "] END ACK(%" PRIu32 ", %" PRIu32 ") Q:%" PRIu32, _server->url(), _clientId, len, time, _messageQueue.size());
355+
346356
_runQueue();
347357
}
348358

@@ -386,7 +396,7 @@ void AsyncWebSocketClient::_runQueue() {
386396
continue;
387397
}
388398
if (space > (size_t)(ctrl.len() - 1)) {
389-
async_ws_log_v("WS[%" PRIu32 "] Sending control frame: %" PRIu8 ", len: %" PRIu8, _clientId, ctrl.opcode(), ctrl.len());
399+
async_ws_log_v("[%s][%" PRIu32 "] SEND CTRL %" PRIu8, _server->url(), _clientId, ctrl.opcode());
390400
ctrl.send(_client);
391401
space = webSocketSendFrameWindow(_client);
392402
}
@@ -397,23 +407,21 @@ void AsyncWebSocketClient::_runQueue() {
397407
if (space) {
398408
for (auto &msg : _messageQueue) {
399409
if (msg._remainingBytesToSend()) {
400-
async_ws_log_v(
401-
"WS[%" PRIu32 "] Send message fragment: %u/%u, acked: %u/%u", _clientId, msg._remainingBytesToSend(), msg._sent + msg._remainingBytesToSend(),
402-
msg._acked, msg._ack
403-
);
410+
async_ws_log_v("[%s][%" PRIu32 "] SEND %u/%u (acked: %u/%u)", _server->url(), _clientId, msg._sent, msg._WSbuffer->size(), msg._acked, msg._ack);
411+
404412
// will use all the remaining space, or all the remaining bytes to send, whichever is smaller
405413
msg.send(_client);
406414
space = webSocketSendFrameWindow(_client);
407415

408416
// If we haven't finished sending this message, we must stop here to preserve WebSocket ordering.
409417
// We can only pipeline subsequent messages if the current one is fully passed to TCP buffer.
410418
if (msg._remainingBytesToSend()) {
419+
async_ws_log_v("[%s][%" PRIu32 "] NO_SPACE", _server->url(), _clientId);
411420
break;
412421
}
413-
}
414-
415-
// not enough space for another message
416-
if (!space) {
422+
} else if (!space) {
423+
// not enough space for another message
424+
async_ws_log_v("[%s][%" PRIu32 "] NO_SPACE", _server->url(), _clientId);
417425
break;
418426
}
419427
}
@@ -452,6 +460,7 @@ bool AsyncWebSocketClient::_queueControl(uint8_t opcode, const uint8_t *data, si
452460
#endif
453461

454462
_controlQueue.emplace_back(opcode, data, len, mask);
463+
async_ws_log_v("[%s][%" PRIu32 "] QUEUE CTRL (%u) + %" PRIu8, _server->url(), _clientId, _controlQueue.size(), opcode);
455464

456465
if (_client && _client->canSend()) {
457466
_runQueue();
@@ -485,16 +494,17 @@ bool AsyncWebSocketClient::_queueMessage(AsyncWebSocketSharedBuffer buffer, uint
485494
_client->close();
486495
}
487496

488-
async_ws_log_w("Too many messages queued: closing connection");
497+
async_ws_log_w("[%s][%" PRIu32 "] Too many messages queued: closing connection", _server->url(), _clientId);
489498

490499
} else {
491-
async_ws_log_w("Too many messages queued: discarding new message");
500+
async_ws_log_w("[%s][%" PRIu32 "] Too many messages queued: discarding new message", _server->url(), _clientId);
492501
}
493502

494503
return false;
495504
}
496505

497506
_messageQueue.emplace_back(buffer, opcode, mask);
507+
async_ws_log_v("[%s][%" PRIu32 "] QUEUE MSG (%u/%u) + %" PRIu8, _server->url(), _clientId, _messageQueue.size(), WS_MAX_QUEUED_MESSAGES, opcode);
498508

499509
if (_client && _client->canSend()) {
500510
_runQueue();
@@ -508,6 +518,8 @@ void AsyncWebSocketClient::close(uint16_t code, const char *message) {
508518
return;
509519
}
510520

521+
async_ws_log_w("[%s][%" PRIu32 "] CLOSE", _server->url(), _clientId);
522+
511523
_status = WS_DISCONNECTING;
512524

513525
if (code) {
@@ -541,21 +553,20 @@ bool AsyncWebSocketClient::ping(const uint8_t *data, size_t len) {
541553
return _status == WS_CONNECTED && _queueControl(WS_PING, data, len);
542554
}
543555

544-
void AsyncWebSocketClient::_onError(int8_t) {
545-
// Serial.println("onErr");
556+
void AsyncWebSocketClient::_onError(int8_t err) {
557+
async_ws_log_v("[%s][%" PRIu32 "] ERROR %" PRIi8, _server->url(), _clientId, static_cast<int8_t>(err));
546558
}
547559

548560
void AsyncWebSocketClient::_onTimeout(uint32_t time) {
549561
if (!_client) {
550562
return;
551563
}
552-
// Serial.println("onTime");
553-
(void)time;
564+
async_ws_log_v("[%s][%" PRIu32 "] TIMEOUT %" PRIu32, _server->url(), _clientId, time);
554565
_client->close();
555566
}
556567

557568
void AsyncWebSocketClient::_onDisconnect() {
558-
// Serial.println("onDis");
569+
async_ws_log_v("[%s][%" PRIu32 "] DISCONNECT", _server->url(), _clientId);
559570
_client = nullptr;
560571
_server->_handleDisconnect(this);
561572
}
@@ -566,7 +577,7 @@ void AsyncWebSocketClient::_onData(void *pbuf, size_t plen) {
566577

567578
while (plen > 0) {
568579
async_ws_log_v(
569-
"WS[%" PRIu32 "] _onData: plen: %" PRIu32 ", _pstate: %" PRIu8 ", _status: %" PRIu8, _clientId, plen, _pstate, static_cast<uint8_t>(_status)
580+
"[%s][%" PRIu32 "] DATA plen: %" PRIu32 ", _pstate: %" PRIu8 ", _status: %" PRIu8, _server->url(), _clientId, plen, _pstate, static_cast<uint8_t>(_status)
570581
);
571582

572583
if (_pstate == STATE_FRAME_START) {
@@ -595,8 +606,8 @@ void AsyncWebSocketClient::_onData(void *pbuf, size_t plen) {
595606
}
596607

597608
async_ws_log_v(
598-
"WS[%" PRIu32 "] _pinfo: index: %" PRIu64 ", final: %" PRIu8 ", opcode: %" PRIu8 ", masked: %" PRIu8 ", len: %" PRIu64, _clientId, _pinfo.index,
599-
_pinfo.final, _pinfo.opcode, _pinfo.masked, _pinfo.len
609+
"[%s][%" PRIu32 "] DATA _pinfo: index: %" PRIu64 ", final: %" PRIu8 ", opcode: %" PRIu8 ", masked: %" PRIu8 ", len: %" PRIu64, _server->url(), _clientId,
610+
_pinfo.index, _pinfo.final, _pinfo.opcode, _pinfo.masked, _pinfo.len
600611
);
601612

602613
// Handle fragmented mask data - Safari may split the 4-byte mask across multiple packets
@@ -608,7 +619,7 @@ void AsyncWebSocketClient::_onData(void *pbuf, size_t plen) {
608619
if (plen == 0) {
609620
// Safari close frame edge case: masked bit set but no mask data
610621
if (_pinfo.opcode == WS_DISCONNECT) {
611-
async_ws_log_v("WS[%" PRIu32 "] close frame with incomplete mask, treating as unmasked", _clientId);
622+
async_ws_log_v("[%s][%" PRIu32 "] DATA close frame with incomplete mask, treating as unmasked", _server->url(), _clientId);
612623
_pinfo.masked = 0;
613624
_pinfo.index = 0;
614625
_pinfo.len = 0;
@@ -618,7 +629,7 @@ void AsyncWebSocketClient::_onData(void *pbuf, size_t plen) {
618629

619630
//wait for more data
620631
_pstate = STATE_FRAME_MASK;
621-
async_ws_log_v("WS[%" PRIu32 "] waiting for more mask data: read: %" PRIu8 "/4", _clientId, _pinfo.masked - 1);
632+
async_ws_log_v("[%s][%" PRIu32 "] DATA waiting for more mask data: read: %" PRIu8 "/4", _server->url(), _clientId, _pinfo.masked - 1);
622633
return;
623634
}
624635

@@ -634,7 +645,7 @@ void AsyncWebSocketClient::_onData(void *pbuf, size_t plen) {
634645

635646
// restore masked to 1 for backward compatibility
636647
if (_pinfo.masked >= 5) {
637-
async_ws_log_v("WS[%" PRIu32 "] mask read complete", _clientId);
648+
async_ws_log_v("[%s][%" PRIu32 "] DATA mask read complete", _server->url(), _clientId);
638649
_pinfo.masked = 1;
639650
}
640651

@@ -663,7 +674,7 @@ void AsyncWebSocketClient::_onData(void *pbuf, size_t plen) {
663674

664675
if (datalen > 0) {
665676
async_ws_log_v(
666-
"WS[%" PRIu32 "] processing next fragment of %s frame %" PRIu32 ", index: %" PRIu64 ", len: %" PRIu32 "", _clientId,
677+
"[%s][%" PRIu32 "] DATA processing next fragment of %s frame %" PRIu32 ", index: %" PRIu64 ", len: %" PRIu32 "", _server->url(), _clientId,
667678
(_pinfo.message_opcode == WS_TEXT) ? "text" : "binary", _pinfo.num, _pinfo.index, (uint32_t)datalen
668679
);
669680
_handleDataEvent(data, datalen, datalen == plen); // datalen == plen means that we are processing the last part of the current TCP packet
@@ -676,7 +687,7 @@ void AsyncWebSocketClient::_onData(void *pbuf, size_t plen) {
676687
_pstate = STATE_FRAME_START;
677688

678689
if (_pinfo.opcode == WS_DISCONNECT) {
679-
async_ws_log_v("WS[%" PRIu32 "] processing disconnect", _clientId);
690+
async_ws_log_v("[%s][%" PRIu32 "] DATA WS_DISCONNECT", _server->url(), _clientId);
680691

681692
if (datalen) {
682693
uint16_t reasonCode = (uint16_t)(data[0] << 8) + data[1];
@@ -699,19 +710,19 @@ void AsyncWebSocketClient::_onData(void *pbuf, size_t plen) {
699710
}
700711

701712
} else if (_pinfo.opcode == WS_PING) {
702-
async_ws_log_v("WS[%" PRIu32 "] processing ping", _clientId);
713+
async_ws_log_v("[%s][%" PRIu32 "] DATA PING", _server->url(), _clientId);
703714
_server->_handleEvent(this, WS_EVT_PING, NULL, NULL, 0);
704715
_queueControl(WS_PONG, data, datalen);
705716

706717
} else if (_pinfo.opcode == WS_PONG) {
707-
async_ws_log_v("WS[%" PRIu32 "] processing pong", _clientId);
718+
async_ws_log_v("[%s][%" PRIu32 "] DATA PONG", _server->url(), _clientId);
708719
if (datalen != AWSC_PING_PAYLOAD_LEN || memcmp(AWSC_PING_PAYLOAD, data, AWSC_PING_PAYLOAD_LEN) != 0) {
709720
_server->_handleEvent(this, WS_EVT_PONG, NULL, NULL, 0);
710721
}
711722

712723
} else if (_pinfo.opcode < WS_DISCONNECT) { // continuation or text/binary frame
713724
async_ws_log_v(
714-
"WS[%" PRIu32 "] processing final fragment of %s frame %" PRIu32 ", index: %" PRIu64 ", len: %" PRIu32 "", _clientId,
725+
"[%s][%" PRIu32 "] DATA processing final fragment of %s frame %" PRIu32 ", index: %" PRIu64 ", len: %" PRIu32 "", _server->url(), _clientId,
715726
(_pinfo.message_opcode == WS_TEXT) ? "text" : "binary", _pinfo.num, _pinfo.index, (uint32_t)datalen
716727
);
717728

@@ -728,7 +739,7 @@ void AsyncWebSocketClient::_onData(void *pbuf, size_t plen) {
728739
// unexpected frame error, close connection
729740
_pstate = STATE_FRAME_START;
730741

731-
async_ws_log_v("frame error: len: %u, index: %llu, total: %llu\n", datalen, _pinfo.index, _pinfo.len);
742+
async_ws_log_v("[%s][%" PRIu32 "] DATA frame error: len: %u, index: %llu, total: %llu\n", _server->url(), _clientId, datalen, _pinfo.index, _pinfo.len);
732743

733744
_status = WS_DISCONNECTING;
734745
if (_client) {
@@ -1038,7 +1049,9 @@ void AsyncWebSocket::closeAll(uint16_t code, const char *message) {
10381049
}
10391050

10401051
void AsyncWebSocket::cleanupClients(uint16_t maxClients) {
1041-
if (count() > maxClients) {
1052+
const size_t c = count();
1053+
if (c > maxClients) {
1054+
async_ws_log_v("[%s] CLEANUP %" PRIu32 " (%" PRIu32 "/%" PRIu16 ")", _url.c_str(), _clients.front().id(), c, maxClients);
10421055
_clients.front().close();
10431056
}
10441057

0 commit comments

Comments
 (0)