Skip to content

Commit e939f7e

Browse files
mathieucarboumathieucarbou
authored
Merge pull request #397 from ESP32Async/logging
Review logging across WebSocket implementation
2 parents 04991a7 + 60c590b commit e939f7e

1 file changed

Lines changed: 53 additions & 35 deletions

File tree

‎src/AsyncWebSocket.cpp‎

Lines changed: 53 additions & 35 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 "] %u/%u (acked: %u/%u) => %" PRIu8, _opcode, _sent, _WSbuffer->size(), _acked, _ack, static_cast<uint8_t>(_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 != %" PRIu8, _opcode, client->remotePort(), static_cast<uint8_t>(_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(%u, %" PRIu32 ") Q:%u", _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(%u, %" PRIu32 ") Q:%u", _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
}
@@ -398,22 +408,23 @@ void AsyncWebSocketClient::_runQueue() {
398408
for (auto &msg : _messageQueue) {
399409
if (msg._remainingBytesToSend()) {
400410
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
411+
"[%s][%" PRIu32 "][%" PRIu8 "] SEND %u/%u (acked: %u/%u)", _server->url(), _clientId, msg._opcode, msg._sent, msg._WSbuffer->size(), msg._acked,
412+
msg._ack
403413
);
414+
404415
// will use all the remaining space, or all the remaining bytes to send, whichever is smaller
405416
msg.send(_client);
406417
space = webSocketSendFrameWindow(_client);
407418

408419
// If we haven't finished sending this message, we must stop here to preserve WebSocket ordering.
409420
// We can only pipeline subsequent messages if the current one is fully passed to TCP buffer.
410421
if (msg._remainingBytesToSend()) {
422+
async_ws_log_v("[%s][%" PRIu32 "][%" PRIu8 "] NO_SPACE", _server->url(), _clientId, msg._opcode);
411423
break;
412424
}
413-
}
414-
415-
// not enough space for another message
416-
if (!space) {
425+
} else if (!space) {
426+
// not enough space for another message
427+
async_ws_log_v("[%s][%" PRIu32 "] NO_SPACE", _server->url(), _clientId);
417428
break;
418429
}
419430
}
@@ -452,6 +463,7 @@ bool AsyncWebSocketClient::_queueControl(uint8_t opcode, const uint8_t *data, si
452463
#endif
453464

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

456468
if (_client && _client->canSend()) {
457469
_runQueue();
@@ -485,16 +497,17 @@ bool AsyncWebSocketClient::_queueMessage(AsyncWebSocketSharedBuffer buffer, uint
485497
_client->close();
486498
}
487499

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

490502
} else {
491-
async_ws_log_w("Too many messages queued: discarding new message");
503+
async_ws_log_w("[%s][%" PRIu32 "] Too many messages queued: discarding new message", _server->url(), _clientId);
492504
}
493505

494506
return false;
495507
}
496508

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

499512
if (_client && _client->canSend()) {
500513
_runQueue();
@@ -508,6 +521,8 @@ void AsyncWebSocketClient::close(uint16_t code, const char *message) {
508521
return;
509522
}
510523

524+
async_ws_log_w("[%s][%" PRIu32 "] CLOSE", _server->url(), _clientId);
525+
511526
_status = WS_DISCONNECTING;
512527

513528
if (code) {
@@ -541,21 +556,20 @@ bool AsyncWebSocketClient::ping(const uint8_t *data, size_t len) {
541556
return _status == WS_CONNECTED && _queueControl(WS_PING, data, len);
542557
}
543558

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

548563
void AsyncWebSocketClient::_onTimeout(uint32_t time) {
549564
if (!_client) {
550565
return;
551566
}
552-
// Serial.println("onTime");
553-
(void)time;
567+
async_ws_log_v("[%s][%" PRIu32 "] TIMEOUT %" PRIu32, _server->url(), _clientId, time);
554568
_client->close();
555569
}
556570

557571
void AsyncWebSocketClient::_onDisconnect() {
558-
// Serial.println("onDis");
572+
async_ws_log_v("[%s][%" PRIu32 "] DISCONNECT", _server->url(), _clientId);
559573
_client = nullptr;
560574
_server->_handleDisconnect(this);
561575
}
@@ -566,7 +580,7 @@ void AsyncWebSocketClient::_onData(void *pbuf, size_t plen) {
566580

567581
while (plen > 0) {
568582
async_ws_log_v(
569-
"WS[%" PRIu32 "] _onData: plen: %" PRIu32 ", _pstate: %" PRIu8 ", _status: %" PRIu8, _clientId, plen, _pstate, static_cast<uint8_t>(_status)
583+
"[%s][%" PRIu32 "] DATA plen: %" PRIu32 ", _pstate: %" PRIu8 ", _status: %" PRIu8, _server->url(), _clientId, plen, _pstate, static_cast<uint8_t>(_status)
570584
);
571585

572586
if (_pstate == STATE_FRAME_START) {
@@ -595,8 +609,8 @@ void AsyncWebSocketClient::_onData(void *pbuf, size_t plen) {
595609
}
596610

597611
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
612+
"[%s][%" PRIu32 "] DATA _pinfo: index: %" PRIu64 ", final: %" PRIu8 ", opcode: %" PRIu8 ", masked: %" PRIu8 ", len: %" PRIu64, _server->url(), _clientId,
613+
_pinfo.index, _pinfo.final, _pinfo.opcode, _pinfo.masked, _pinfo.len
600614
);
601615

602616
// Handle fragmented mask data - Safari may split the 4-byte mask across multiple packets
@@ -608,17 +622,17 @@ void AsyncWebSocketClient::_onData(void *pbuf, size_t plen) {
608622
if (plen == 0) {
609623
// Safari close frame edge case: masked bit set but no mask data
610624
if (_pinfo.opcode == WS_DISCONNECT) {
611-
async_ws_log_v("WS[%" PRIu32 "] close frame with incomplete mask, treating as unmasked", _clientId);
625+
async_ws_log_v("[%s][%" PRIu32 "] DATA close frame with incomplete mask, treating as unmasked", _server->url(), _clientId);
612626
_pinfo.masked = 0;
613627
_pinfo.index = 0;
614628
_pinfo.len = 0;
615629
_pstate = STATE_FRAME_START;
616630
break;
617631
}
618632

619-
//wait for more data
633+
// wait for more data
620634
_pstate = STATE_FRAME_MASK;
621-
async_ws_log_v("WS[%" PRIu32 "] waiting for more mask data: read: %" PRIu8 "/4", _clientId, _pinfo.masked - 1);
635+
async_ws_log_v("[%s][%" PRIu32 "] DATA waiting for more mask data: read: %" PRIu8 "/4", _server->url(), _clientId, _pinfo.masked - 1);
622636
return;
623637
}
624638

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

635649
// restore masked to 1 for backward compatibility
636650
if (_pinfo.masked >= 5) {
637-
async_ws_log_v("WS[%" PRIu32 "] mask read complete", _clientId);
651+
async_ws_log_v("[%s][%" PRIu32 "] DATA mask read complete", _server->url(), _clientId);
638652
_pinfo.masked = 1;
639653
}
640654

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

664678
if (datalen > 0) {
665679
async_ws_log_v(
666-
"WS[%" PRIu32 "] processing next fragment of %s frame %" PRIu32 ", index: %" PRIu64 ", len: %" PRIu32 "", _clientId,
680+
"[%s][%" PRIu32 "] DATA processing next fragment of %s frame %" PRIu32 ", index: %" PRIu64 ", len: %" PRIu32 "", _server->url(), _clientId,
667681
(_pinfo.message_opcode == WS_TEXT) ? "text" : "binary", _pinfo.num, _pinfo.index, (uint32_t)datalen
668682
);
669683
_handleDataEvent(data, datalen, datalen == plen); // datalen == plen means that we are processing the last part of the current TCP packet
@@ -676,7 +690,7 @@ void AsyncWebSocketClient::_onData(void *pbuf, size_t plen) {
676690
_pstate = STATE_FRAME_START;
677691

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

681695
if (datalen) {
682696
uint16_t reasonCode = (uint16_t)(data[0] << 8) + data[1];
@@ -699,19 +713,19 @@ void AsyncWebSocketClient::_onData(void *pbuf, size_t plen) {
699713
}
700714

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

706720
} else if (_pinfo.opcode == WS_PONG) {
707-
async_ws_log_v("WS[%" PRIu32 "] processing pong", _clientId);
721+
async_ws_log_v("[%s][%" PRIu32 "] DATA PONG", _server->url(), _clientId);
708722
if (datalen != AWSC_PING_PAYLOAD_LEN || memcmp(AWSC_PING_PAYLOAD, data, AWSC_PING_PAYLOAD_LEN) != 0) {
709723
_server->_handleEvent(this, WS_EVT_PONG, NULL, NULL, 0);
710724
}
711725

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

@@ -728,7 +742,9 @@ void AsyncWebSocketClient::_onData(void *pbuf, size_t plen) {
728742
// unexpected frame error, close connection
729743
_pstate = STATE_FRAME_START;
730744

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

733749
_status = WS_DISCONNECTING;
734750
if (_client) {
@@ -1038,7 +1054,9 @@ void AsyncWebSocket::closeAll(uint16_t code, const char *message) {
10381054
}
10391055

10401056
void AsyncWebSocket::cleanupClients(uint16_t maxClients) {
1041-
if (count() > maxClients) {
1057+
const size_t c = count();
1058+
if (c > maxClients) {
1059+
async_ws_log_v("[%s] CLEANUP %" PRIu32 " (%u/%" PRIu16 ")", _url.c_str(), _clients.front().id(), c, maxClients);
10421060
_clients.front().close();
10431061
}
10441062

0 commit comments

Comments
 (0)