QUIC library is ignoring error log settings
maciek-szn opened this issue · 7 comments
maciek-szn commented
From time to time, entries from the QUIC library appear in the error log, ignoring the logging level set for OLS. These are thousands of lines at the DEBUG level even though the OLS Debug Level setting is set to None. This significantly increases the size of the error log and makes its analysis more difficult.
My OLS settings:
(changing Log Level to INFO doesn't change anything)
Error log snippet:
2024-02-06 22:58:47.248354 [WARN] [980] Detected QUIC busy loop at 100
2024-02-06 22:58:47.248503 [WARN] [980] Detected QUIC busy loop at 200
2024-02-06 22:58:47.248607 [WARN] [980] Detected QUIC busy loop at 300
2024-02-06 22:58:47.248710 [WARN] [980] Detected QUIC busy loop at 400
2024-02-06 22:58:47.248813 [WARN] [980] Detected QUIC busy loop at 500
2024-02-06 22:58:47.248833 [INFO] logger: set pacer to info
2024-02-06 22:58:47.248839 [DEBUG] engine: next advisory tick is now: have 1 tickable connection (560E8FB77A034775 first)
2024-02-06 22:58:47.248845 [DEBUG] engine: decref conn 560E8FB77A034775, 'HT' -> 'H'
2024-02-06 22:58:47.248849 [DEBUG] [QUIC:560E8FB77A034775] hpi: read-0: add stream 2
2024-02-06 22:58:47.248854 [DEBUG] [QUIC:560E8FB77A034775] hpi: read-0: lsquic_hpi_next: return stream 2, incr: 1, priority 0
2024-02-06 22:58:47.248859 [DEBUG] [QUIC:560E8FB77A034775] sendctl: send_ctl_can_send: n_out: 701 (unacked_all: 701); cwnd: 46720; ccfc: 773/16777216
2024-02-06 22:58:47.248865 [DEBUG] [QUIC:560E8FB77A034775] hpi: write-high: add stream 0
2024-02-06 22:58:47.248888 [DEBUG] [QUIC:560E8FB77A034775] hpi: write-high: lsquic_hpi_next: return stream 0, incr: 1, priority 1
2024-02-06 22:58:47.248893 [DEBUG] [QUIC:560E8FB77A034775] sendctl: send_ctl_can_send: n_out: 701 (unacked_all: 701); cwnd: 46720; ccfc: 773/16777216
2024-02-06 22:58:47.248897 [DEBUG] [QUIC:560E8FB77A034775-0] stream: dispatch_write_events
2024-02-06 22:58:47.248901 [DEBUG] [QUIC:560E8FB77A034775] sendctl: send_ctl_can_send: n_out: 701 (unacked_all: 701); cwnd: 46720; ccfc: 773/16777216
2024-02-06 22:58:47.248905 [DEBUG] [QUIC:560E8FB77A034775] sendctl: send_ctl_can_send: n_out: 701 (unacked_all: 701); cwnd: 46720; ccfc: 773/16777216
2024-02-06 22:58:47.248910 [DEBUG] [QUIC:560E8FB77A034775] hpi: write-low: add stream 0
2024-02-06 22:58:47.248913 [DEBUG] [QUIC:560E8FB77A034775] hpi: write-low: lsquic_hpi_next: return stream 0, incr: 1, priority 1
2024-02-06 22:58:47.248917 [DEBUG] [QUIC:560E8FB77A034775] sendctl: send_ctl_can_send: n_out: 701 (unacked_all: 701); cwnd: 46720; ccfc: 773/16777216
2024-02-06 22:58:47.248921 [DEBUG] [QUIC:560E8FB77A034775-0] stream: dispatch_write_events
[thousands of DEBUG entries]
2024-02-06 22:58:47.343122 [DEBUG] engine: decref conn 560E8FB77A034775, 'HOK' -> 'HK'
2024-02-06 22:58:47.343127 [DEBUG] engine: send_packets_out: sent 1 packet
2024-02-06 22:58:47.343147 [DEBUG] engine: decref conn 560E8FB77A034775, 'HK' -> 'H'
2024-02-06 22:58:47.343152 [DEBUG] [QUIC:560E8FB77A034775] conn: not tickable
2024-02-06 22:58:47.343158 [DEBUG] engine: incref conn 560E8FB77A034775, 'H' -> 'HA'
2024-02-06 22:58:47.343169 [DEBUG] [980] [UDP:0.0.0.0:443] onRead: done; in total, read 1 packet in 1 batch
2024-02-06 22:58:47.343175 [DEBUG] engine: next advisory tick is 14213 usec away: conn 560E8FB77A034775: RETX_APP
2024-02-06 22:58:47.343185 [WARN] [980] End QUIC busy loop at 503
litespeedtech commented
It has been fixed in the most recent update of 1.7.19, please update with
/usr/local/lsws/admin/misc/lsup.sh -v 1.7.19
Or, update rpm/debian package if installed via package repo.
maciek-szn commented
Well, it wasn't fixed. I wrote this report 16 hours after updating to version 1.7.19-3 and the problem still persists.
litespeedtech commented
You can give the latest OLS 1.8.0 a try.
/usr/loca/lsws/admin/misc/lsup.sh -v 1.8.0