diff --git a/.gitignore b/.gitignore index 10a0d15df99..767cb1e17ad 100644 --- a/.gitignore +++ b/.gitignore @@ -97,8 +97,9 @@ iocore/eventsystem/test_MIOBufferWriter iocore/hostdb/test_RefCountCache proxy/hdrs/test_mime +proxy/hdrs/test_Huffmancode +proxy/hdrs/test_XPACK proxy/http/test_ForwardedConfig -proxy/http2/test_Huffmancode proxy/http2/test_Http2DependencyTree proxy/http2/test_Http2FrequencyCounter proxy/http2/test_HPACK diff --git a/doc/admin-guide/files/records.config.en.rst b/doc/admin-guide/files/records.config.en.rst index 109122e2a8b..060ee746e9e 100644 --- a/doc/admin-guide/files/records.config.en.rst +++ b/doc/admin-guide/files/records.config.en.rst @@ -2882,6 +2882,26 @@ Logging Configuration completion will cause its timing stats to be written to the :ts:cv:`debugging log file `. This is identifying data about the transaction and all of the :c:type:`transaction milestones `. +.. ts:cv:: CONFIG proxy.config.http2.connection.slow.log.threshold INT 0 + :reloadable: + :units: milliseconds + + If set to a non-zero value :arg:`N` then any HTTP/2 connection + that takes longer than :arg:`N` milliseconds from open to close will cause + its timing stats to be written to the :ts:cv:`debugging log file + `. This is identifying data about the + transaction and all of the :c:type:`transaction milestones `. + +.. ts:cv:: CONFIG proxy.config.http2.stream.slow.log.threshold INT 0 + :reloadable: + :units: milliseconds + + If set to a non-zero value :arg:`N` then any HTTP/2 stream + that takes longer than :arg:`N` milliseconds from open to close will cause + its timing stats to be written to the :ts:cv:`debugging log file + `. This is identifying data about the + transaction and all of the :c:type:`transaction milestones `. + .. ts:cv:: CONFIG proxy.config.log.config.filename STRING logging.yaml :reloadable: @@ -3507,7 +3527,15 @@ HTTP/2 Configuration :reloadable: The maximum size of the header compression table used to decode header - blocks. + blocks. This value will be advertised as SETTINGS_HEADER_TABLE_SIZE. + +.. ts:cv:: CONFIG proxy.config.http2.header_table_size_limit INT 65536 + :reloadable: + + The maximum size of the header compression table ATS actually use when ATS + encodes headers. Setting 0 means ATS doesn't insert headers into HPACK + Dynamic Table, however, headers still can be encoded as indexable + representations. The upper limit is 65536. .. ts:cv:: CONFIG proxy.config.http2.max_header_list_size INT 4294967295 :reloadable: @@ -3603,7 +3631,9 @@ HTTP/2 Configuration Specifies how many number of PRIORITY frames |TS| receives for a minute at maximum. Clients exceeded this limit will be immediately disconnected with an error - code of ENHANCE_YOUR_CALM. + code of ENHANCE_YOUR_CALM. If this is set to 0, the limit logic is disabled. + This limit only will be enforced if :ts:cv:`proxy.config.http2.stream_priority_enabled` + is set to 1. .. ts:cv:: CONFIG proxy.config.http2.min_avg_window_update FLOAT 2560.0 :reloadable: diff --git a/doc/admin-guide/monitoring/statistics/core/http-connection.en.rst b/doc/admin-guide/monitoring/statistics/core/http-connection.en.rst index 736850ebcda..d2e9014ffde 100644 --- a/doc/admin-guide/monitoring/statistics/core/http-connection.en.rst +++ b/doc/admin-guide/monitoring/statistics/core/http-connection.en.rst @@ -136,7 +136,111 @@ HTTP Connection This tracks the number of origin connections denied due to being over the :ts:cv:`proxy.config.http.origin_max_connections` limit. -.. ts:stat:: global proxy.process.http2.current_active_client_connections integer + +HTTP/2 +------ + + +.. ts:stat:: global proxy.process.http2.total_client_connections integer + :type: counter + + Represents the total number of HTTP/2 connections from client to the |TS|. + +.. ts:stat:: global proxy.process.http2.current_client_connections integer :type: gauge Represents the current number of HTTP/2 connections from client to the |TS|. + +.. ts:stat:: global proxy.process.http2.current_active_client_connections integer + :type: gauge + + Represents the current number of HTTP/2 active connections from client to the |TS|. + +.. ts:stat:: global proxy.process.http2.connection_errors integer + :type: counter + + Represents the total number of HTTP/2 connections errors. + +.. ts:stat:: global proxy.process.http2.session_die_default integer + :type: counter + + Represents the total number of closed HTTP/2 connections with + ``VC_EVENT_NONE`` event. + +.. ts:stat:: global proxy.process.http2.session_die_active integer + :type: counter + + Represents the total number of closed HTTP/2 connections with + ``VC_EVENT_ACTIVE_TIMEOUT`` event. + +.. ts:stat:: global proxy.process.http2.session_die_inactive integer + :type: counter + + Represents the total number of closed HTTP/2 connections with + ``VC_EVENT_INACTIVITY_TIMEOUT`` event. + +.. ts:stat:: global proxy.process.http2.session_die_eos integer + :type: counter + + Represents the total number of closed HTTP/2 connections with + ``VC_EVENT_EOS`` event. + +.. ts:stat:: global proxy.process.http2.session_die_error integer + :type: counter + + Represents the total number of closed HTTP/2 connections with + ``VC_EVENT_ERROR`` event. + +.. ts:stat:: global proxy.process.http2.session_die_other integer + :type: counter + + Represents the total number of closed HTTP/2 connections with + unknown event. + +.. ts:stat:: global proxy.process.http2.session_die_high_error_rate integer + :type: counter + + Represents the total number of closed HTTP/2 connections with high + error rate which is configured by :ts:cv:`proxy.config.http2.stream_error_rate_threshold`. + +.. ts:stat:: global proxy.process.http2.max_settings_per_frame_exceeded integer + :type: counter + + Represents the total number of closed HTTP/2 connections for exceeding the + maximum allowed number of settings per frame limit which is configured by + :ts:cv:`proxy.config.http2.max_settings_per_frame`. + +.. ts:stat:: global proxy.process.http2.max_settings_per_minute_exceeded integer + :type: counter + + Represents the total number of closed HTTP/2 connections for exceeding the + maximum allowed number of settings per minute limit which is configured by + :ts:cv:`proxy.config.http2.max_settings_per_minute`. + +.. ts:stat:: global proxy.process.http2.max_settings_frames_per_minute_exceeded integer + :type: counter + + Represents the total number of closed HTTP/2 connections for exceeding the + maximum allowed number of settings frames per minute limit which is configured by + :ts:cv:`proxy.config.http2.max_settings_frames_per_minute`. + +.. ts:stat:: global proxy.process.http2.max_ping_frames_per_minute_exceeded integer + :type: counter + + Represents the total number of closed HTTP/2 connections for exceeding the + maximum allowed number of ping frames per minute limit which is configured by + :ts:cv:`proxy.config.http2.max_ping_frames_per_minute`. + +.. ts:stat:: global proxy.process.http2.max_priority_frames_per_minute_exceeded integer + :type: counter + + Represents the total number of closed HTTP/2 connections for exceeding the + maximum allowed number of priority frames per minute limit which is configured by + :ts:cv:`proxy.config.http2.max_priority_frames_per_minute`. + +.. ts:stat:: global proxy.process.http2.insufficient_avg_window_update integer + :type: counter + + Represents the total number of closed HTTP/2 connections for not reaching the + minimum average window increment limit which is configured by + :ts:cv:`proxy.config.http2.min_avg_window_update`. diff --git a/doc/admin-guide/monitoring/statistics/core/http-transaction.en.rst b/doc/admin-guide/monitoring/statistics/core/http-transaction.en.rst index fd5772bb764..07a6e60a0d8 100644 --- a/doc/admin-guide/monitoring/statistics/core/http-transaction.en.rst +++ b/doc/admin-guide/monitoring/statistics/core/http-transaction.en.rst @@ -150,3 +150,28 @@ HTTP Transaction :units: seconds :ungathered: + +HTTP/2 +------ + + +.. ts:stat:: global proxy.process.http2.total_client_streams integer + :type: counter + + Represents the total number of HTTP/2 streams from client to the |TS|. + +.. ts:stat:: global proxy.process.http2.current_client_streams integer + :type: gauge + + Represents the current number of HTTP/2 streams from client to the |TS|. + +.. ts:stat:: global proxy.process.http2.total_transactions_time integer + :type: counter + :units: seconds + + Represents the total transaction time of HTTP/2 streams from client to the |TS|. + +.. ts:stat:: global proxy.process.http2.stream_errors integer + :type: counter + + Represents the total number of HTTP/2 stream errors. diff --git a/mgmt/RecordsConfig.cc b/mgmt/RecordsConfig.cc index 72a501f95a4..e7dc9475523 100644 --- a/mgmt/RecordsConfig.cc +++ b/mgmt/RecordsConfig.cc @@ -658,6 +658,10 @@ static const RecordElement RecordsConfig[] = , {RECT_CONFIG, "proxy.config.http.slow.log.threshold", RECD_INT, "0", RECU_DYNAMIC, RR_NULL, RECC_STR, "^[0-9]+$", RECA_NULL} , + {RECT_CONFIG, "proxy.config.http2.connection.slow.log.threshold", RECD_INT, "0", RECU_DYNAMIC, RR_NULL, RECC_STR, "^[0-9]+$", RECA_NULL} + , + {RECT_CONFIG, "proxy.config.http2.stream.slow.log.threshold", RECD_INT, "0", RECU_DYNAMIC, RR_NULL, RECC_STR, "^[0-9]+$", RECA_NULL} + , //############################################################################## //# @@ -1342,6 +1346,8 @@ static const RecordElement RecordsConfig[] = , {RECT_CONFIG, "proxy.config.http2.min_avg_window_update", RECD_FLOAT, "2560.0", RECU_DYNAMIC, RR_NULL, RECC_NULL, nullptr, RECA_NULL} , + {RECT_CONFIG, "proxy.config.http2.header_table_size_limit", RECD_INT, "65536", RECU_DYNAMIC, RR_NULL, RECC_STR, "^[0-9]+$", RECA_NULL} + , //# Add LOCAL Records Here {RECT_LOCAL, "proxy.local.incoming_ip_to_bind", RECD_STRING, nullptr, RECU_NULL, RR_NULL, RECC_NULL, nullptr, RECA_NULL} diff --git a/proxy/Milestones.h b/proxy/Milestones.h index d429e285b81..3170c0f38e0 100644 --- a/proxy/Milestones.h +++ b/proxy/Milestones.h @@ -1,6 +1,6 @@ /** @file - A brief file description + Milestones @section license License @@ -23,22 +23,32 @@ #pragma once -#include "tscore/ink_platform.h" -#include "tscore/ink_hrtime.h" #include "ts/apidefs.h" + +#include "tscore/ink_platform.h" #include "tscore/ink_hrtime.h" -///////////////////////////////////////////////////////////// -// -// class TransactionMilestones -// -///////////////////////////////////////////////////////////// -class TransactionMilestones +#include "I_EventSystem.h" + +template class Milestones { public: - TransactionMilestones() { ink_zero(milestones); } - ink_hrtime &operator[](TSMilestonesType ms) { return milestones[ms]; } - ink_hrtime operator[](TSMilestonesType ms) const { return milestones[ms]; } + ink_hrtime &operator[](T ms) { return this->_milestones[static_cast(ms)]; } + ink_hrtime operator[](T ms) const { return this->_milestones[static_cast(ms)]; } + + /** + * Mark given milestone with timestamp if it's not marked yet + * @param ms The milestone to mark + * @return N/A + */ + void + mark(T ms) + { + if (this->_milestones[static_cast(ms)] == 0) { + this->_milestones[static_cast(ms)] = Thread::get_hrtime(); + } + } + /** * Takes two milestones and returns the difference. * @param start The start time @@ -46,12 +56,12 @@ class TransactionMilestones * @return The difference time in milliseconds */ int64_t - difference_msec(TSMilestonesType ms_start, TSMilestonesType ms_end) const + difference_msec(T ms_start, T ms_end) const { - if (milestones[ms_end] == 0) { + if (this->_milestones[static_cast(ms_end)] == 0) { return -1; } - return ink_hrtime_to_msec(milestones[ms_end] - milestones[ms_start]); + return ink_hrtime_to_msec(this->_milestones[static_cast(ms_end)] - this->_milestones[static_cast(ms_start)]); } /** @@ -61,17 +71,26 @@ class TransactionMilestones * @return A double that is the difference time in seconds */ double - difference_sec(TSMilestonesType ms_start, TSMilestonesType ms_end) const + difference_sec(T ms_start, T ms_end) const { - return (double)difference_msec(ms_start, ms_end) / 1000.0; + return static_cast(difference_msec(ms_start, ms_end) / 1000.0); } + /** + * Takes two milestones and returns the difference. + * @param start The start time + * @param end The end time + * @return The difference time in high-resolution time + */ ink_hrtime - elapsed(TSMilestonesType ms_start, TSMilestonesType ms_end) const + elapsed(T ms_start, T ms_end) const { - return milestones[ms_end] - milestones[ms_start]; + return this->_milestones[static_cast(ms_end)] - this->_milestones[static_cast(ms_start)]; } private: - ink_hrtime milestones[TS_MILESTONE_LAST_ENTRY]; + std::array _milestones = {0}; }; + +// For compatibility with HttpSM.h and HttpTransact.h +using TransactionMilestones = Milestones; diff --git a/proxy/http2/HuffmanCodec.cc b/proxy/hdrs/HuffmanCodec.cc similarity index 100% rename from proxy/http2/HuffmanCodec.cc rename to proxy/hdrs/HuffmanCodec.cc diff --git a/proxy/http2/HuffmanCodec.h b/proxy/hdrs/HuffmanCodec.h similarity index 100% rename from proxy/http2/HuffmanCodec.h rename to proxy/hdrs/HuffmanCodec.h diff --git a/proxy/hdrs/Makefile.am b/proxy/hdrs/Makefile.am index 42dad696a94..bc060e527c4 100644 --- a/proxy/hdrs/Makefile.am +++ b/proxy/hdrs/Makefile.am @@ -43,7 +43,11 @@ libhdrs_a_SOURCES = \ MIME.cc \ MIME.h \ URL.cc \ - URL.h + URL.h \ + HuffmanCodec.cc \ + HuffmanCodec.h \ + XPACK.cc \ + XPACK.h if BUILD_TESTS libhdrs_a_SOURCES += \ @@ -62,9 +66,12 @@ load_http_hdr_LDADD = -L. -lhdrs \ $(top_builddir)/src/tscpp/util/libtscpputil.la \ @LIBTCL@ -check_PROGRAMS = test_mime +check_PROGRAMS = \ + test_mime \ + test_Huffmancode \ + test_XPACK -TESTS = test_mime +TESTS = $(check_PROGRAMS) test_mime_LDADD = -L. -lhdrs \ $(top_builddir)/src/tscore/libtscore.la \ @@ -78,6 +85,28 @@ test_mime_LDADD = -L. -lhdrs \ test_mime_SOURCES = test_mime.cc +test_Huffmancode_LDADD = \ + $(top_builddir)/src/tscore/libtscore.la \ + $(top_builddir)/src/tscpp/util/libtscpputil.la + +test_Huffmancode_SOURCES = \ + test_Huffmancode.cc \ + HuffmanCodec.cc \ + HuffmanCodec.h + +test_XPACK_CPPFLAGS = \ + $(AM_CPPFLAGS) \ + -I$(abs_top_srcdir)/tests/include + +test_XPACK_LDADD = \ + $(top_builddir)/src/tscore/libtscore.la \ + $(top_builddir)/src/tscpp/util/libtscpputil.la + +test_XPACK_SOURCES = \ + unit_tests/test_XPACK.cc \ + HuffmanCodec.cc \ + XPACK.cc + #test_UNUSED_SOURCES = \ # test_urlhash.cc diff --git a/proxy/hdrs/XPACK.cc b/proxy/hdrs/XPACK.cc new file mode 100644 index 00000000000..e987479b933 --- /dev/null +++ b/proxy/hdrs/XPACK.cc @@ -0,0 +1,202 @@ +/** @file + + Common functions for HPACK and QPACK + + @section license License + + Licensed to the Apache Software Foundation (ASF) under one + or more contributor license agreements. See the NOTICE file + distributed with this work for additional information + regarding copyright ownership. The ASF licenses this file + to you under the Apache License, Version 2.0 (the + "License"); you may not use this file except in compliance + with the License. You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + + Unless required by applicable law or agreed to in writing, software + distributed under the License is distributed on an "AS IS" BASIS, + WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + See the License for the specific language governing permissions and + limitations under the License. + */ + +#include "tscore/Arena.h" +#include "tscore/ink_memory.h" +#include "XPACK.h" +#include "HuffmanCodec.h" + +// +// [RFC 7541] 5.1. Integer representation +// +int64_t +xpack_decode_integer(uint64_t &dst, const uint8_t *buf_start, const uint8_t *buf_end, uint8_t n) +{ + if (buf_start >= buf_end) { + return XPACK_ERROR_COMPRESSION_ERROR; + } + + const uint8_t *p = buf_start; + + dst = (*p & ((1 << n) - 1)); + if (dst == static_cast(1 << n) - 1) { + int m = 0; + do { + if (++p >= buf_end) { + return XPACK_ERROR_COMPRESSION_ERROR; + } + + uint64_t added_value = *p & 0x7f; + if ((UINT64_MAX >> m) < added_value) { + // Excessively large integer encodings - in value or octet + // length - MUST be treated as a decoding error. + return XPACK_ERROR_COMPRESSION_ERROR; + } + dst += added_value << m; + m += 7; + } while (*p & 0x80); + } + + return p - buf_start + 1; +} + +// +// [RFC 7541] 5.2. String Literal Representation +// return content from String Data (Length octets) with huffman decoding if it is encoded +// +int64_t +xpack_decode_string(Arena &arena, char **str, uint64_t &str_length, const uint8_t *buf_start, const uint8_t *buf_end, uint8_t n) +{ + if (buf_start >= buf_end) { + return XPACK_ERROR_COMPRESSION_ERROR; + } + + const uint8_t *p = buf_start; + bool isHuffman = *p & (0x01 << n); + uint64_t encoded_string_len = 0; + int64_t len = 0; + + len = xpack_decode_integer(encoded_string_len, p, buf_end, n); + if (len == XPACK_ERROR_COMPRESSION_ERROR) { + return XPACK_ERROR_COMPRESSION_ERROR; + } + p += len; + + if ((p + encoded_string_len) > buf_end) { + return XPACK_ERROR_COMPRESSION_ERROR; + } + + if (isHuffman) { + // Allocate temporary area twice the size of before decoded data + *str = arena.str_alloc(encoded_string_len * 2); + + len = huffman_decode(*str, p, encoded_string_len); + if (len < 0) { + return XPACK_ERROR_COMPRESSION_ERROR; + } + str_length = len; + } else { + *str = arena.str_alloc(encoded_string_len); + + memcpy(*str, reinterpret_cast(p), encoded_string_len); + + str_length = encoded_string_len; + } + + return p + encoded_string_len - buf_start; +} + +// +// [RFC 7541] 5.1. Integer representation +// +int64_t +xpack_encode_integer(uint8_t *buf_start, const uint8_t *buf_end, uint64_t value, uint8_t n) +{ + if (buf_start >= buf_end) { + return -1; + } + + uint8_t *p = buf_start; + + // Preserve the first n bits + uint8_t prefix = *buf_start & (0xFF << n); + + if (value < (static_cast(1 << n) - 1)) { + *(p++) = value; + } else { + *(p++) = (1 << n) - 1; + value -= (1 << n) - 1; + while (value >= 128) { + if (p >= buf_end) { + return -1; + } + *(p++) = (value & 0x7F) | 0x80; + value = value >> 7; + } + if (p + 1 >= buf_end) { + return -1; + } + *(p++) = value; + } + + // Restore the prefix + *buf_start |= prefix; + + return p - buf_start; +} + +int64_t +xpack_encode_string(uint8_t *buf_start, const uint8_t *buf_end, const char *value, uint64_t value_len, uint8_t n) +{ + uint8_t *p = buf_start; + bool use_huffman = true; + char *data = nullptr; + int64_t data_len = 0; + + // TODO Choose whether to use Huffman encoding wisely + // cppcheck-suppress knownConditionTrueFalse; leaving "use_huffman" for wise huffman usage in the future + if (use_huffman && value_len) { + data = static_cast(ats_malloc(value_len * 4)); + if (data == nullptr) { + return -1; + } + data_len = huffman_encode(reinterpret_cast(data), reinterpret_cast(value), value_len); + } + + // Length + const int64_t len = xpack_encode_integer(p, buf_end, data_len, n); + if (len == -1) { + if (use_huffman) { + ats_free(data); + } + + return -1; + } + + if (use_huffman) { + *p |= 0x01 << n; + } else { + *p &= ~(0x01 << n); + } + p += len; + + if (buf_end < p || buf_end - p < data_len) { + if (use_huffman) { + ats_free(data); + } + + return -1; + } + + // Value + if (data_len) { + memcpy(p, data, data_len); + p += data_len; + } + + if (use_huffman) { + ats_free(data); + } + + return p - buf_start; +} diff --git a/proxy/hdrs/XPACK.h b/proxy/hdrs/XPACK.h new file mode 100644 index 00000000000..70814a512b0 --- /dev/null +++ b/proxy/hdrs/XPACK.h @@ -0,0 +1,37 @@ +/** @file + * + * A brief file description + * + * @section license License + * + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +#pragma once + +#include +#include "tscore/Arena.h" + +const static int XPACK_ERROR_COMPRESSION_ERROR = -1; +const static int XPACK_ERROR_SIZE_EXCEEDED_ERROR = -2; + +// These primitives are shared with HPACK and QPACK. +int64_t xpack_encode_integer(uint8_t *buf_start, const uint8_t *buf_end, uint64_t value, uint8_t n); +int64_t xpack_decode_integer(uint64_t &dst, const uint8_t *buf_start, const uint8_t *buf_end, uint8_t n); +int64_t xpack_encode_string(uint8_t *buf_start, const uint8_t *buf_end, const char *value, uint64_t value_len, uint8_t n = 7); +int64_t xpack_decode_string(Arena &arena, char **str, uint64_t &str_length, const uint8_t *buf_start, const uint8_t *buf_end, + uint8_t n = 7); diff --git a/proxy/http2/test_Huffmancode.cc b/proxy/hdrs/test_Huffmancode.cc similarity index 100% rename from proxy/http2/test_Huffmancode.cc rename to proxy/hdrs/test_Huffmancode.cc diff --git a/proxy/hdrs/unit_tests/test_XPACK.cc b/proxy/hdrs/unit_tests/test_XPACK.cc new file mode 100644 index 00000000000..91bd8b31161 --- /dev/null +++ b/proxy/hdrs/unit_tests/test_XPACK.cc @@ -0,0 +1,123 @@ +/** @file + + Catch based unit tests for XPACK + + @section license License + + Licensed to the Apache Software Foundation (ASF) under one + or more contributor license agreements. See the NOTICE file + distributed with this work for additional information + regarding copyright ownership. The ASF licenses this file + to you under the Apache License, Version 2.0 (the + "License"); you may not use this file except in compliance + with the License. You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + + Unless required by applicable law or agreed to in writing, software + distributed under the License is distributed on an "AS IS" BASIS, + WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + See the License for the specific language governing permissions and + limitations under the License. + */ + +#define CATCH_CONFIG_MAIN + +#include "catch.hpp" + +#include "XPACK.h" +#include "HuffmanCodec.h" + +static constexpr int BUFSIZE_FOR_REGRESSION_TEST = 128; + +TEST_CASE("XPACK_Integer", "[xpack]") +{ + // [RFC 7541] C.1. Integer Representation Examples + static const struct { + uint32_t raw_integer; + uint8_t *encoded_field; + int encoded_field_len; + int prefix; + } integer_test_case[] = {{10, (uint8_t *)"\x0a", 1, 5}, {1337, (uint8_t *)"\x1F\x9A\x0A", 3, 5}, {42, (uint8_t *)R"(*)", 1, 8}}; + + SECTION("Encoding") + { + for (const auto &i : integer_test_case) { + uint8_t buf[BUFSIZE_FOR_REGRESSION_TEST] = {0}; + + int len = xpack_encode_integer(buf, buf + BUFSIZE_FOR_REGRESSION_TEST, i.raw_integer, i.prefix); + + REQUIRE(len > 0); + REQUIRE(len == i.encoded_field_len); + REQUIRE(memcmp(buf, i.encoded_field, len) == 0); + } + } + + SECTION("Decoding") + { + for (const auto &i : integer_test_case) { + uint64_t actual = 0; + int len = xpack_decode_integer(actual, i.encoded_field, i.encoded_field + i.encoded_field_len, i.prefix); + + REQUIRE(len == i.encoded_field_len); + REQUIRE(actual == i.raw_integer); + } + } +} + +TEST_CASE("XPACK_String", "[xpack]") +{ + // Example: custom-key: custom-header + const static struct { + char *raw_string; + uint32_t raw_string_len; + uint8_t *encoded_field; + int encoded_field_len; + } string_test_case[] = {{(char *)"", 0, + (uint8_t *)"\x0" + "", + 1}, + {(char *)"custom-key", 10, + (uint8_t *)"\xA" + "custom-key", + 11}, + {(char *)"", 0, + (uint8_t *)"\x80" + "", + 1}, + {(char *)"custom-key", 10, + (uint8_t *)"\x88" + "\x25\xa8\x49\xe9\x5b\xa9\x7d\x7f", + 9}}; + + SECTION("Encoding") + { + // FIXME Current encoder support only huffman conding. + for (unsigned int i = 2; i < sizeof(string_test_case) / sizeof(string_test_case[0]); i++) { + uint8_t buf[BUFSIZE_FOR_REGRESSION_TEST] = {0}; + int len = xpack_encode_string(buf, buf + BUFSIZE_FOR_REGRESSION_TEST, string_test_case[i].raw_string, + string_test_case[i].raw_string_len); + + REQUIRE(len > 0); + REQUIRE(len == string_test_case[i].encoded_field_len); + REQUIRE(memcmp(buf, string_test_case[i].encoded_field, len) == 0); + } + } + + SECTION("Decoding") + { + // Decoding string needs huffman tree + hpack_huffman_init(); + + for (const auto &i : string_test_case) { + Arena arena; + char *actual = nullptr; + uint64_t actual_len = 0; + int len = xpack_decode_string(arena, &actual, actual_len, i.encoded_field, i.encoded_field + i.encoded_field_len); + + REQUIRE(len == i.encoded_field_len); + REQUIRE(actual_len == i.raw_string_len); + REQUIRE(memcmp(actual, i.raw_string, actual_len) == 0); + } + } +} diff --git a/proxy/http2/HPACK.cc b/proxy/http2/HPACK.cc index 80b4c06cbff..4dcf72942d8 100644 --- a/proxy/http2/HPACK.cc +++ b/proxy/http2/HPACK.cc @@ -354,7 +354,7 @@ HpackDynamicTable::~HpackDynamicTable() const MIMEField * HpackDynamicTable::get_header_field(uint32_t index) const { - return this->_headers.at(this->_headers.size() - index - 1); + return this->_headers.at(index); } void @@ -380,8 +380,7 @@ HpackDynamicTable::add_header_field(const MIMEField *field) MIMEField *new_field = this->_mhdr->field_create(name, name_len); new_field->value_set(this->_mhdr->m_heap, this->_mhdr->m_mime, value, value_len); this->_mhdr->field_attach(new_field); - // XXX Because entire Vec instance is copied, Its too expensive! - this->_headers.push_back(new_field); + this->_headers.push_front(new_field); } } @@ -414,7 +413,7 @@ HpackDynamicTable::update_maximum_size(uint32_t new_size) uint32_t HpackDynamicTable::length() const { - return _headers.size(); + return this->_headers.size(); } bool @@ -425,23 +424,20 @@ HpackDynamicTable::_evict_overflowed_entries() return true; } - size_t count = 0; - for (auto &h : this->_headers) { + for (auto h = this->_headers.rbegin(); h != this->_headers.rend(); ++h) { int name_len, value_len; - h->name_get(&name_len); - h->value_get(&value_len); + (*h)->name_get(&name_len); + (*h)->value_get(&value_len); this->_current_size -= ADDITIONAL_OCTETS + name_len + value_len; - this->_mhdr->field_delete(h, false); - ++count; + this->_mhdr->field_delete(*h, false); + this->_headers.pop_back(); if (this->_current_size <= this->_maximum_size) { break; } } - this->_headers.erase(this->_headers.begin(), this->_headers.begin() + count); - if (this->_headers.size() == 0) { return false; } @@ -472,92 +468,6 @@ HpackDynamicTable::_mime_hdr_gc() } } -// -// [RFC 7541] 5.1. Integer representation -// -int64_t -encode_integer(uint8_t *buf_start, const uint8_t *buf_end, uint32_t value, uint8_t n) -{ - if (buf_start >= buf_end) { - return -1; - } - - uint8_t *p = buf_start; - - if (value < (static_cast(1 << n) - 1)) { - *(p++) = value; - } else { - *(p++) = (1 << n) - 1; - value -= (1 << n) - 1; - while (value >= 128) { - if (p >= buf_end) { - return -1; - } - *(p++) = (value & 0x7F) | 0x80; - value = value >> 7; - } - if (p + 1 >= buf_end) { - return -1; - } - *(p++) = value; - } - return p - buf_start; -} - -int64_t -encode_string(uint8_t *buf_start, const uint8_t *buf_end, const char *value, size_t value_len) -{ - uint8_t *p = buf_start; - bool use_huffman = true; - char *data = nullptr; - int64_t data_len = 0; - - // TODO Choose whether to use Huffman encoding wisely - - if (use_huffman && value_len) { - data = static_cast(ats_malloc(value_len * 4)); - if (data == nullptr) { - return -1; - } - data_len = huffman_encode(reinterpret_cast(data), reinterpret_cast(value), value_len); - } - - // Length - const int64_t len = encode_integer(p, buf_end, data_len, 7); - if (len == -1) { - if (use_huffman) { - ats_free(data); - } - - return -1; - } - - if (use_huffman) { - *p |= 0x80; - } - p += len; - - if (buf_end < p || buf_end - p < data_len) { - if (use_huffman) { - ats_free(data); - } - - return -1; - } - - // Value - if (data_len) { - memcpy(p, data, data_len); - p += data_len; - } - - if (use_huffman) { - ats_free(data); - } - - return p - buf_start; -} - int64_t encode_indexed_header_field(uint8_t *buf_start, const uint8_t *buf_end, uint32_t index) { @@ -568,7 +478,7 @@ encode_indexed_header_field(uint8_t *buf_start, const uint8_t *buf_end, uint32_t uint8_t *p = buf_start; // Index - const int64_t len = encode_integer(p, buf_end, index, 7); + const int64_t len = xpack_encode_integer(p, buf_end, index, 7); if (len == -1) { return -1; } @@ -614,7 +524,8 @@ encode_literal_header_field_with_indexed_name(uint8_t *buf_start, const uint8_t } // Index - len = encode_integer(p, buf_end, index, prefix); + *p = 0; + len = xpack_encode_integer(p, buf_end, index, prefix); if (len == -1) { return -1; } @@ -629,7 +540,7 @@ encode_literal_header_field_with_indexed_name(uint8_t *buf_start, const uint8_t // Value String int value_len; const char *value = header.value_get(&value_len); - len = encode_string(p, buf_end, value, value_len); + len = xpack_encode_string(p, buf_end, value, value_len); if (len == -1) { return -1; } @@ -679,7 +590,7 @@ encode_literal_header_field_with_new_name(uint8_t *buf_start, const uint8_t *buf } // Name String - len = encode_string(p, buf_end, lower_name, name_len); + len = xpack_encode_string(p, buf_end, lower_name, name_len); if (len == -1) { return -1; } @@ -688,7 +599,7 @@ encode_literal_header_field_with_new_name(uint8_t *buf_start, const uint8_t *buf // Value String int value_len; const char *value = header.value_get(&value_len); - len = encode_string(p, buf_end, value, value_len); + len = xpack_encode_string(p, buf_end, value, value_len); if (len == -1) { return -1; } @@ -702,95 +613,15 @@ encode_literal_header_field_with_new_name(uint8_t *buf_start, const uint8_t *buf int64_t encode_dynamic_table_size_update(uint8_t *buf_start, const uint8_t *buf_end, uint32_t size) { - const int64_t len = encode_integer(buf_start, buf_end, size, 5); + buf_start[0] = 0x20; + const int64_t len = xpack_encode_integer(buf_start, buf_end, size, 5); if (len == -1) { return -1; } - buf_start[0] |= 0x20; return len; } -// -// [RFC 7541] 5.1. Integer representation -// -int64_t -decode_integer(uint32_t &dst, const uint8_t *buf_start, const uint8_t *buf_end, uint8_t n) -{ - if (buf_start >= buf_end) { - return HPACK_ERROR_COMPRESSION_ERROR; - } - - const uint8_t *p = buf_start; - - dst = (*p & ((1 << n) - 1)); - if (dst == static_cast(1 << n) - 1) { - int m = 0; - do { - if (++p >= buf_end) { - return HPACK_ERROR_COMPRESSION_ERROR; - } - - uint32_t added_value = *p & 0x7f; - if ((UINT32_MAX >> m) < added_value) { - // Excessively large integer encodings - in value or octet - // length - MUST be treated as a decoding error. - return HPACK_ERROR_COMPRESSION_ERROR; - } - dst += added_value << m; - m += 7; - } while (*p & 0x80); - } - - return p - buf_start + 1; -} - -// -// [RFC 7541] 5.2. String Literal Representation -// return content from String Data (Length octets) with huffman decoding if it is encoded -// -int64_t -decode_string(Arena &arena, char **str, uint32_t &str_length, const uint8_t *buf_start, const uint8_t *buf_end) -{ - if (buf_start >= buf_end) { - return HPACK_ERROR_COMPRESSION_ERROR; - } - - const uint8_t *p = buf_start; - bool isHuffman = *p & 0x80; - uint32_t encoded_string_len = 0; - int64_t len = 0; - - len = decode_integer(encoded_string_len, p, buf_end, 7); - if (len == HPACK_ERROR_COMPRESSION_ERROR) { - return HPACK_ERROR_COMPRESSION_ERROR; - } - p += len; - - if ((p + encoded_string_len) > buf_end) { - return HPACK_ERROR_COMPRESSION_ERROR; - } - - if (isHuffman) { - // Allocate temporary area twice the size of before decoded data - *str = arena.str_alloc(encoded_string_len * 2); - - len = huffman_decode(*str, p, encoded_string_len); - if (len < 0) { - return HPACK_ERROR_COMPRESSION_ERROR; - } - str_length = len; - } else { - *str = arena.str_alloc(encoded_string_len); - - memcpy(*str, reinterpret_cast(p), encoded_string_len); - - str_length = encoded_string_len; - } - - return p + encoded_string_len - buf_start; -} - // // [RFC 7541] 6.1. Indexed Header Field Representation // @@ -798,11 +629,11 @@ int64_t decode_indexed_header_field(MIMEFieldWrapper &header, const uint8_t *buf_start, const uint8_t *buf_end, HpackIndexingTable &indexing_table) { - uint32_t index = 0; + uint64_t index = 0; int64_t len = 0; - len = decode_integer(index, buf_start, buf_end, 7); - if (len == HPACK_ERROR_COMPRESSION_ERROR) { + len = xpack_decode_integer(index, buf_start, buf_end, 7); + if (len == XPACK_ERROR_COMPRESSION_ERROR) { return HPACK_ERROR_COMPRESSION_ERROR; } @@ -834,22 +665,22 @@ decode_literal_header_field(MIMEFieldWrapper &header, const uint8_t *buf_start, { const uint8_t *p = buf_start; bool isIncremental = false; - uint32_t index = 0; + uint64_t index = 0; int64_t len = 0; HpackField ftype = hpack_parse_field_type(*p); bool has_http2_violation = false; if (ftype == HpackField::INDEXED_LITERAL) { - len = decode_integer(index, p, buf_end, 6); + len = xpack_decode_integer(index, p, buf_end, 6); isIncremental = true; } else if (ftype == HpackField::NEVERINDEX_LITERAL) { - len = decode_integer(index, p, buf_end, 4); + len = xpack_decode_integer(index, p, buf_end, 4); } else { ink_assert(ftype == HpackField::NOINDEX_LITERAL); - len = decode_integer(index, p, buf_end, 4); + len = xpack_decode_integer(index, p, buf_end, 4); } - if (len == HPACK_ERROR_COMPRESSION_ERROR) { + if (len == XPACK_ERROR_COMPRESSION_ERROR) { return HPACK_ERROR_COMPRESSION_ERROR; } @@ -862,10 +693,10 @@ decode_literal_header_field(MIMEFieldWrapper &header, const uint8_t *buf_start, indexing_table.get_header_field(index, header); } else { char *name_str = nullptr; - uint32_t name_str_len = 0; + uint64_t name_str_len = 0; - len = decode_string(arena, &name_str, name_str_len, p, buf_end); - if (len == HPACK_ERROR_COMPRESSION_ERROR) { + len = xpack_decode_string(arena, &name_str, name_str_len, p, buf_end); + if (len == XPACK_ERROR_COMPRESSION_ERROR) { return HPACK_ERROR_COMPRESSION_ERROR; } @@ -884,10 +715,10 @@ decode_literal_header_field(MIMEFieldWrapper &header, const uint8_t *buf_start, // Decode header field value char *value_str = nullptr; - uint32_t value_str_len = 0; + uint64_t value_str_len = 0; - len = decode_string(arena, &value_str, value_str_len, p, buf_end); - if (len == HPACK_ERROR_COMPRESSION_ERROR) { + len = xpack_decode_string(arena, &value_str, value_str_len, p, buf_end); + if (len == XPACK_ERROR_COMPRESSION_ERROR) { return HPACK_ERROR_COMPRESSION_ERROR; } @@ -930,9 +761,9 @@ update_dynamic_table_size(const uint8_t *buf_start, const uint8_t *buf_end, Hpac } // Update header table size if its required. - uint32_t size = 0; - int64_t len = decode_integer(size, buf_start, buf_end, 5); - if (len == HPACK_ERROR_COMPRESSION_ERROR) { + uint64_t size = 0; + int64_t len = xpack_decode_integer(size, buf_start, buf_end, 5); + if (len == XPACK_ERROR_COMPRESSION_ERROR) { return HPACK_ERROR_COMPRESSION_ERROR; } diff --git a/proxy/http2/HPACK.h b/proxy/http2/HPACK.h index 5aa8ad5ac1c..34d1f6d4359 100644 --- a/proxy/http2/HPACK.h +++ b/proxy/http2/HPACK.h @@ -26,8 +26,9 @@ #include "tscore/ink_platform.h" #include "tscore/Diags.h" #include "HTTP.h" +#include "../hdrs/XPACK.h" -#include +#include // It means that any header field can be compressed/decompressed by ATS const static int HPACK_ERROR_COMPRESSION_ERROR = -1; @@ -131,7 +132,7 @@ class HpackDynamicTable MIMEHdr *_mhdr = nullptr; MIMEHdr *_mhdr_old = nullptr; - std::vector _headers; + std::deque _headers; }; // [RFC 7541] 2.3. Indexing Table @@ -154,10 +155,6 @@ class HpackIndexingTable }; // Low level interfaces -int64_t encode_integer(uint8_t *buf_start, const uint8_t *buf_end, uint32_t value, uint8_t n); -int64_t decode_integer(uint32_t &dst, const uint8_t *buf_start, const uint8_t *buf_end, uint8_t n); -int64_t encode_string(uint8_t *buf_start, const uint8_t *buf_end, const char *value, size_t value_len); -int64_t decode_string(Arena &arena, char **str, uint32_t &str_length, const uint8_t *buf_start, const uint8_t *buf_end); int64_t encode_indexed_header_field(uint8_t *buf_start, const uint8_t *buf_end, uint32_t index); int64_t encode_literal_header_field_with_indexed_name(uint8_t *buf_start, const uint8_t *buf_end, const MIMEFieldWrapper &header, uint32_t index, HpackIndexingTable &indexing_table, HpackField type); diff --git a/proxy/http2/HTTP2.cc b/proxy/http2/HTTP2.cc index a74415bb06b..5be510856bd 100644 --- a/proxy/http2/HTTP2.cc +++ b/proxy/http2/HTTP2.cc @@ -23,7 +23,6 @@ #include "HTTP2.h" #include "HPACK.h" -#include "HuffmanCodec.h" #include "tscore/ink_assert.h" #include "records/P_RecCore.h" #include "records/P_RecProcess.h" @@ -43,8 +42,8 @@ const unsigned HTTP2_LEN_AUTHORITY = countof(":authority") - 1; const unsigned HTTP2_LEN_PATH = countof(":path") - 1; const unsigned HTTP2_LEN_STATUS = countof(":status") - 1; -static size_t HTTP2_LEN_STATUS_VALUE_STR = 3; -static const int HTTP2_MAX_TABLE_SIZE_LIMIT = 64 * 1024; +static size_t HTTP2_LEN_STATUS_VALUE_STR = 3; +static const uint32_t HTTP2_MAX_TABLE_SIZE_LIMIT = 64 * 1024; // Statistics RecRawStatBlock *http2_rsb; @@ -64,6 +63,15 @@ static const char *const HTTP2_STAT_SESSION_DIE_INACTIVE_NAME = "pro static const char *const HTTP2_STAT_SESSION_DIE_EOS_NAME = "proxy.process.http2.session_die_eos"; static const char *const HTTP2_STAT_SESSION_DIE_ERROR_NAME = "proxy.process.http2.session_die_error"; static const char *const HTTP2_STAT_SESSION_DIE_HIGH_ERROR_RATE_NAME = "proxy.process.http2.session_die_high_error_rate"; +static const char *const HTTP2_STAT_MAX_SETTINGS_PER_FRAME_EXCEEDED_NAME = "proxy.process.http2.max_settings_per_frame_exceeded"; +static const char *const HTTP2_STAT_MAX_SETTINGS_PER_MINUTE_EXCEEDED_NAME = "proxy.process.http2.max_settings_per_minute_exceeded"; +static const char *const HTTP2_STAT_MAX_SETTINGS_FRAMES_PER_MINUTE_EXCEEDED_NAME = + "proxy.process.http2.max_settings_frames_per_minute_exceeded"; +static const char *const HTTP2_STAT_MAX_PING_FRAMES_PER_MINUTE_EXCEEDED_NAME = + "proxy.process.http2.max_ping_frames_per_minute_exceeded"; +static const char *const HTTP2_STAT_MAX_PRIORITY_FRAMES_PER_MINUTE_EXCEEDED_NAME = + "proxy.process.http2.max_priority_frames_per_minute_exceeded"; +static const char *const HTTP2_STAT_INSUFFICIENT_AVG_WINDOW_UPDATE_NAME = "proxy.process.http2.insufficient_avg_window_update"; union byte_pointer { byte_pointer(void *p) : ptr(p) {} @@ -589,8 +597,9 @@ Http2ErrorCode http2_encode_header_blocks(HTTPHdr *in, uint8_t *out, uint32_t out_len, uint32_t *len_written, HpackHandle &handle, int32_t maximum_table_size) { - // Limit the maximum table size to 64kB, which is the size advertised by major clients - maximum_table_size = std::min(maximum_table_size, HTTP2_MAX_TABLE_SIZE_LIMIT); + // Limit the maximum table size to the configured value or 64kB at maximum, which is the size advertised by major clients + maximum_table_size = + std::min(maximum_table_size, static_cast(std::min(Http2::header_table_size_limit, HTTP2_MAX_TABLE_SIZE_LIMIT))); // Set maximum table size only if it is different from current maximum size if (maximum_table_size == hpack_get_maximum_table_size(handle)) { maximum_table_size = -1; @@ -741,6 +750,9 @@ uint32_t Http2::max_settings_frames_per_minute = 14; uint32_t Http2::max_ping_frames_per_minute = 60; uint32_t Http2::max_priority_frames_per_minute = 120; float Http2::min_avg_window_update = 2560.0; +uint32_t Http2::con_slow_log_threshold = 0; +uint32_t Http2::stream_slow_log_threshold = 0; +uint32_t Http2::header_table_size_limit = 65536; void Http2::init() @@ -765,6 +777,9 @@ Http2::init() REC_EstablishStaticConfigInt32U(max_ping_frames_per_minute, "proxy.config.http2.max_ping_frames_per_minute"); REC_EstablishStaticConfigInt32U(max_priority_frames_per_minute, "proxy.config.http2.max_priority_frames_per_minute"); REC_EstablishStaticConfigFloat(min_avg_window_update, "proxy.config.http2.min_avg_window_update"); + REC_EstablishStaticConfigInt32U(con_slow_log_threshold, "proxy.config.http2.connection.slow.log.threshold"); + REC_EstablishStaticConfigInt32U(stream_slow_log_threshold, "proxy.config.http2.stream.slow.log.threshold"); + REC_EstablishStaticConfigInt32U(header_table_size_limit, "proxy.config.http2.header_table_size_limit"); // If any settings is broken, ATS should not start ink_release_assert(http2_settings_parameter_is_valid({HTTP2_SETTINGS_MAX_CONCURRENT_STREAMS, max_concurrent_streams_in})); @@ -817,6 +832,18 @@ Http2::init() static_cast(HTTP2_STAT_SESSION_DIE_ERROR), RecRawStatSyncSum); RecRegisterRawStat(http2_rsb, RECT_PROCESS, HTTP2_STAT_SESSION_DIE_HIGH_ERROR_RATE_NAME, RECD_INT, RECP_PERSISTENT, static_cast(HTTP2_STAT_SESSION_DIE_HIGH_ERROR_RATE), RecRawStatSyncSum); + RecRegisterRawStat(http2_rsb, RECT_PROCESS, HTTP2_STAT_MAX_SETTINGS_PER_FRAME_EXCEEDED_NAME, RECD_INT, RECP_PERSISTENT, + static_cast(HTTP2_STAT_MAX_SETTINGS_PER_FRAME_EXCEEDED), RecRawStatSyncSum); + RecRegisterRawStat(http2_rsb, RECT_PROCESS, HTTP2_STAT_MAX_SETTINGS_PER_MINUTE_EXCEEDED_NAME, RECD_INT, RECP_PERSISTENT, + static_cast(HTTP2_STAT_MAX_SETTINGS_PER_MINUTE_EXCEEDED), RecRawStatSyncSum); + RecRegisterRawStat(http2_rsb, RECT_PROCESS, HTTP2_STAT_MAX_SETTINGS_FRAMES_PER_MINUTE_EXCEEDED_NAME, RECD_INT, RECP_PERSISTENT, + static_cast(HTTP2_STAT_MAX_SETTINGS_FRAMES_PER_MINUTE_EXCEEDED), RecRawStatSyncSum); + RecRegisterRawStat(http2_rsb, RECT_PROCESS, HTTP2_STAT_MAX_PING_FRAMES_PER_MINUTE_EXCEEDED_NAME, RECD_INT, RECP_PERSISTENT, + static_cast(HTTP2_STAT_MAX_PING_FRAMES_PER_MINUTE_EXCEEDED), RecRawStatSyncSum); + RecRegisterRawStat(http2_rsb, RECT_PROCESS, HTTP2_STAT_MAX_PRIORITY_FRAMES_PER_MINUTE_EXCEEDED_NAME, RECD_INT, RECP_PERSISTENT, + static_cast(HTTP2_STAT_MAX_PRIORITY_FRAMES_PER_MINUTE_EXCEEDED), RecRawStatSyncSum); + RecRegisterRawStat(http2_rsb, RECT_PROCESS, HTTP2_STAT_INSUFFICIENT_AVG_WINDOW_UPDATE_NAME, RECD_INT, RECP_PERSISTENT, + static_cast(HTTP2_STAT_INSUFFICIENT_AVG_WINDOW_UPDATE), RecRawStatSyncSum); } #if TS_HAS_TESTS diff --git a/proxy/http2/HTTP2.h b/proxy/http2/HTTP2.h index 504b899169b..660ecbb4bf0 100644 --- a/proxy/http2/HTTP2.h +++ b/proxy/http2/HTTP2.h @@ -84,6 +84,12 @@ enum { HTTP2_STAT_SESSION_DIE_EOS, HTTP2_STAT_SESSION_DIE_ERROR, HTTP2_STAT_SESSION_DIE_HIGH_ERROR_RATE, + HTTP2_STAT_MAX_SETTINGS_PER_FRAME_EXCEEDED, + HTTP2_STAT_MAX_SETTINGS_PER_MINUTE_EXCEEDED, + HTTP2_STAT_MAX_SETTINGS_FRAMES_PER_MINUTE_EXCEEDED, + HTTP2_STAT_MAX_PING_FRAMES_PER_MINUTE_EXCEEDED, + HTTP2_STAT_MAX_PRIORITY_FRAMES_PER_MINUTE_EXCEEDED, + HTTP2_STAT_INSUFFICIENT_AVG_WINDOW_UPDATE, HTTP2_N_STATS // Terminal counter, NOT A STAT INDEX. }; @@ -239,7 +245,7 @@ struct Http2FrameHeader { // [RFC 7540] 5.4. Error Handling struct Http2Error { Http2Error(const Http2ErrorClass error_class = Http2ErrorClass::HTTP2_ERROR_CLASS_NONE, - const Http2ErrorCode error_code = Http2ErrorCode::HTTP2_ERROR_NO_ERROR, const char *err_msg = nullptr) + const Http2ErrorCode error_code = Http2ErrorCode::HTTP2_ERROR_NO_ERROR, const char *err_msg = "") { cls = error_class; code = error_code; @@ -385,6 +391,9 @@ class Http2 static uint32_t max_ping_frames_per_minute; static uint32_t max_priority_frames_per_minute; static float min_avg_window_update; + static uint32_t con_slow_log_threshold; + static uint32_t stream_slow_log_threshold; + static uint32_t header_table_size_limit; static void init(); }; diff --git a/proxy/http2/Http2ClientSession.cc b/proxy/http2/Http2ClientSession.cc index cddc4ec21f0..29d62b8215a 100644 --- a/proxy/http2/Http2ClientSession.cc +++ b/proxy/http2/Http2ClientSession.cc @@ -25,8 +25,14 @@ #include "HttpDebugNames.h" #include "tscore/ink_base64.h" +#define REMEMBER(e, r) \ + { \ + this->remember(MakeSourceLocation(), e, r); \ + } + #define STATE_ENTER(state_name, event) \ do { \ + REMEMBER(event, this->recursion) \ SsnDebug(this, "http2_cs", "[%" PRId64 "] [%s, %s]", this->connection_id(), #state_name, \ HttpDebugNames::get_event_name(event)); \ } while (0) @@ -35,6 +41,7 @@ #define HTTP2_SET_SESSION_HANDLER(handler) \ do { \ + REMEMBER(NO_EVENT, this->recursion); \ this->session_handler = (handler); \ } while (0) @@ -65,6 +72,7 @@ Http2ClientSession::destroy() { if (!in_destroy) { in_destroy = true; + REMEMBER(NO_EVENT, this->recursion) Http2SsnDebug("session destroy"); // Let everyone know we are going down do_api_callout(TS_HTTP_SSN_CLOSE_HOOK); @@ -96,8 +104,19 @@ Http2ClientSession::free() return; } + REMEMBER(NO_EVENT, this->recursion) Http2SsnDebug("session free"); + this->_milestones.mark(Http2SsnMilestone::CLOSE); + ink_hrtime total_time = this->_milestones.elapsed(Http2SsnMilestone::OPEN, Http2SsnMilestone::CLOSE); + + // Slow Log + if (Http2::con_slow_log_threshold != 0 && ink_hrtime_from_msec(Http2::con_slow_log_threshold) < total_time) { + Error("[%" PRIu64 "] Slow H2 Connection: open: %" PRIu64 " close: %.3f", this->con_id, + ink_hrtime_to_msec(this->_milestones[Http2SsnMilestone::OPEN]), + this->_milestones.difference_sec(Http2SsnMilestone::OPEN, Http2SsnMilestone::CLOSE)); + } + HTTP2_DECREMENT_THREAD_DYN_STAT(HTTP2_STAT_CURRENT_CLIENT_SESSION_COUNT, this->mutex->thread_holding); // Update stats on how we died. May want to eliminate this. Was useful for @@ -150,25 +169,20 @@ Http2ClientSession::free() void Http2ClientSession::start() { - VIO *read_vio; - SCOPED_MUTEX_LOCK(lock, this->mutex, this_ethread()); SET_HANDLER(&Http2ClientSession::main_event_handler); HTTP2_SET_SESSION_HANDLER(&Http2ClientSession::state_read_connection_preface); - read_vio = this->do_io_read(this, INT64_MAX, this->read_buffer); - write_vio = this->do_io_write(this, INT64_MAX, this->sm_writer); - - // 3.5 HTTP/2 Connection Preface. Upon establishment of a TCP connection and - // determination that HTTP/2 will be used by both peers, each endpoint MUST - // send a connection preface as a final confirmation ... - // this->write_buffer->write(HTTP2_CONNECTION_PREFACE, - // HTTP2_CONNECTION_PREFACE_LEN); + VIO *read_vio = this->do_io_read(this, INT64_MAX, this->read_buffer); + write_vio = this->do_io_write(this, INT64_MAX, this->sm_writer); this->connection_state.init(); send_connection_event(&this->connection_state, HTTP2_SESSION_EVENT_INIT, this); - this->handleEvent(VC_EVENT_READ_READY, read_vio); + + if (this->sm_reader->is_read_avail_more_than(0)) { + this->handleEvent(VC_EVENT_READ_READY, read_vio); + } } void @@ -177,6 +191,7 @@ Http2ClientSession::new_connection(NetVConnection *new_vc, MIOBuffer *iobuf, IOB ink_assert(new_vc->mutex->thread_holding == this_ethread()); HTTP2_INCREMENT_THREAD_DYN_STAT(HTTP2_STAT_CURRENT_CLIENT_SESSION_COUNT, new_vc->mutex->thread_holding); HTTP2_INCREMENT_THREAD_DYN_STAT(HTTP2_STAT_TOTAL_CLIENT_CONNECTION_COUNT, new_vc->mutex->thread_holding); + this->_milestones.mark(Http2SsnMilestone::OPEN); // HTTP/2 for the backdoor connections? Let's not deal woth that yet. ink_release_assert(backdoor == false); @@ -271,6 +286,7 @@ Http2ClientSession::do_io_shutdown(ShutdownHowTo_t howto) void Http2ClientSession::do_io_close(int alerrno) { + REMEMBER(NO_EVENT, this->recursion) Http2SsnDebug("session closed"); ink_assert(this->mutex->thread_holding == this_ethread()); @@ -556,8 +572,9 @@ Http2ClientSession::state_process_frame_read(int event, VIO *vio, bool inside_fr } while (this->sm_reader->read_avail() >= (int64_t)HTTP2_FRAME_HEADER_LEN) { - // Cancel reading if there was an error - if (connection_state.tx_error_code.code != static_cast(Http2ErrorCode::HTTP2_ERROR_NO_ERROR)) { + // Cancel reading if there was an error or connection is closed + if (connection_state.tx_error_code.code != static_cast(Http2ErrorCode::HTTP2_ERROR_NO_ERROR) || + connection_state.is_state_closed()) { Http2SsnDebug("reading a frame has been canceled (%u)", connection_state.tx_error_code.code); break; } @@ -621,6 +638,12 @@ Http2ClientSession::decrement_current_active_client_connections_stat() HTTP2_DECREMENT_THREAD_DYN_STAT(HTTP2_STAT_CURRENT_ACTIVE_CLIENT_CONNECTION_COUNT, this_ethread()); } +void +Http2ClientSession::remember(const SourceLocation &location, int event, int reentrant) +{ + this->_history.push_back(location, event, reentrant); +} + bool Http2ClientSession::_should_do_something_else() { diff --git a/proxy/http2/Http2ClientSession.h b/proxy/http2/Http2ClientSession.h index e8b43a55a86..f99dd30d22b 100644 --- a/proxy/http2/Http2ClientSession.h +++ b/proxy/http2/Http2ClientSession.h @@ -29,6 +29,8 @@ #include "Http2ConnectionState.h" #include #include "tscore/ink_inet.h" +#include "tscore/History.h" +#include "Milestones.h" // Name Edata Description // HTTP2_SESSION_EVENT_INIT Http2ClientSession * HTTP/2 session is born @@ -49,6 +51,12 @@ enum class Http2SessionCod : int { HIGH_ERROR_RATE, }; +enum class Http2SsnMilestone { + OPEN = 0, + CLOSE, + LAST_ENTRY, +}; + size_t const HTTP2_HEADER_BUFFER_SIZE_INDEX = CLIENT_CONNECTION_FIRST_READ_BUFFER_SIZE_INDEX; // To support Upgrade: h2c @@ -310,11 +318,8 @@ class Http2ClientSession : public ProxyClientSession } } - int64_t - write_buffer_size() - { - return write_buffer->max_read_avail(); - } + // Record history from Http2ConnectionState + void remember(const SourceLocation &location, int event, int reentrant = NO_REENTRANT); // noncopyable Http2ClientSession(Http2ClientSession &) = delete; @@ -347,6 +352,9 @@ class Http2ClientSession : public ProxyClientSession IpEndpoint cached_client_addr; IpEndpoint cached_local_addr; + History _history; + Milestones(Http2SsnMilestone::LAST_ENTRY)> _milestones; + // For Upgrade: h2c Http2UpgradeContext upgrade_context; diff --git a/proxy/http2/Http2ConnectionState.cc b/proxy/http2/Http2ConnectionState.cc index 5fc3a9ee325..869e0ee200a 100644 --- a/proxy/http2/Http2ConnectionState.cc +++ b/proxy/http2/Http2ConnectionState.cc @@ -26,9 +26,17 @@ #include "Http2ClientSession.h" #include "Http2Stream.h" #include "Http2DebugNames.h" +#include "HttpDebugNames.h" #include #include +#define REMEMBER(e, r) \ + { \ + if (this->ua_session) { \ + this->ua_session->remember(MakeSourceLocation(), e, r); \ + } \ + } + #define Http2ConDebug(ua_session, fmt, ...) \ SsnDebug(ua_session, "http2_con", "[%" PRId64 "] " fmt, ua_session->connection_id(), ##__VA_ARGS__); @@ -329,6 +337,7 @@ rcv_headers_frame(Http2ConnectionState &cstate, const Http2Frame &frame) empty_request = true; } + stream->mark_milestone(Http2StreamMilestone::START_DECODE_HEADERS); Http2ErrorCode result = stream->decode_header_blocks(*cstate.local_hpack_handle, cstate.server_settings.get(HTTP2_SETTINGS_HEADER_TABLE_SIZE)); @@ -348,6 +357,7 @@ rcv_headers_frame(Http2ConnectionState &cstate, const Http2Frame &frame) // Set up the State Machine if (!empty_request) { SCOPED_MUTEX_LOCK(stream_lock, stream->mutex, this_ethread()); + stream->mark_milestone(Http2StreamMilestone::START_TXN); stream->new_transaction(); // Send request header to SM stream->send_request(cstate); @@ -407,10 +417,16 @@ rcv_priority_frame(Http2ConnectionState &cstate, const Http2Frame &frame) "PRIORITY frame depends on itself"); } + if (!Http2::stream_priority_enabled) { + return Http2Error(Http2ErrorClass::HTTP2_ERROR_CLASS_NONE); + } + // Update PRIORITY frame count per minute cstate.increment_received_priority_frame_count(); // Close this conection if its priority frame count received exceeds a limit - if (cstate.get_received_priority_frame_count() > Http2::max_priority_frames_per_minute) { + if (Http2::max_priority_frames_per_minute != 0 && + cstate.get_received_priority_frame_count() > Http2::max_priority_frames_per_minute) { + HTTP2_INCREMENT_THREAD_DYN_STAT(HTTP2_STAT_MAX_PRIORITY_FRAMES_PER_MINUTE_EXCEEDED, this_ethread()); Http2StreamDebug(cstate.ua_session, stream_id, "Observed too frequent priority changes: %u priority changes within a last minute", cstate.get_received_priority_frame_count()); @@ -418,10 +434,6 @@ rcv_priority_frame(Http2ConnectionState &cstate, const Http2Frame &frame) "recv priority too frequent priority changes"); } - if (!Http2::stream_priority_enabled) { - return Http2Error(Http2ErrorClass::HTTP2_ERROR_CLASS_NONE); - } - Http2StreamDebug(cstate.ua_session, stream_id, "PRIORITY - dep: %d, weight: %d, excl: %d, tree size: %d", priority.stream_dependency, priority.weight, priority.exclusive_flag, cstate.dependency_tree->size()); @@ -527,6 +539,7 @@ rcv_settings_frame(Http2ConnectionState &cstate, const Http2Frame &frame) cstate.increment_received_settings_frame_count(); // Close this conection if its SETTINGS frame count exceeds a limit if (cstate.get_received_settings_frame_count() > Http2::max_settings_frames_per_minute) { + HTTP2_INCREMENT_THREAD_DYN_STAT(HTTP2_STAT_MAX_SETTINGS_FRAMES_PER_MINUTE_EXCEEDED, this_ethread()); Http2StreamDebug(cstate.ua_session, stream_id, "Observed too frequent SETTINGS frames: %u frames within a last minute", cstate.get_received_settings_frame_count()); return Http2Error(Http2ErrorClass::HTTP2_ERROR_CLASS_CONNECTION, Http2ErrorCode::HTTP2_ERROR_ENHANCE_YOUR_CALM, @@ -565,6 +578,7 @@ rcv_settings_frame(Http2ConnectionState &cstate, const Http2Frame &frame) uint32_t n_settings = 0; while (nbytes < frame.header().length) { if (n_settings >= Http2::max_settings_per_frame) { + HTTP2_INCREMENT_THREAD_DYN_STAT(HTTP2_STAT_MAX_SETTINGS_PER_FRAME_EXCEEDED, this_ethread()); Http2StreamDebug(cstate.ua_session, stream_id, "Observed too many settings in a frame"); return Http2Error(Http2ErrorClass::HTTP2_ERROR_CLASS_CONNECTION, Http2ErrorCode::HTTP2_ERROR_ENHANCE_YOUR_CALM, "recv settings too many settings in a frame"); @@ -605,6 +619,7 @@ rcv_settings_frame(Http2ConnectionState &cstate, const Http2Frame &frame) cstate.increment_received_settings_count(n_settings); // Close this conection if its settings count received exceeds a limit if (cstate.get_received_settings_count() > Http2::max_settings_per_minute) { + HTTP2_INCREMENT_THREAD_DYN_STAT(HTTP2_STAT_MAX_SETTINGS_PER_MINUTE_EXCEEDED, this_ethread()); Http2StreamDebug(cstate.ua_session, stream_id, "Observed too frequent setting changes: %u settings within a last minute", cstate.get_received_settings_count()); return Http2Error(Http2ErrorClass::HTTP2_ERROR_CLASS_CONNECTION, Http2ErrorCode::HTTP2_ERROR_ENHANCE_YOUR_CALM, @@ -658,6 +673,7 @@ rcv_ping_frame(Http2ConnectionState &cstate, const Http2Frame &frame) cstate.increment_received_ping_frame_count(); // Close this conection if its ping count received exceeds a limit if (cstate.get_received_ping_frame_count() > Http2::max_ping_frames_per_minute) { + HTTP2_INCREMENT_THREAD_DYN_STAT(HTTP2_STAT_MAX_PING_FRAMES_PER_MINUTE_EXCEEDED, this_ethread()); Http2StreamDebug(cstate.ua_session, stream_id, "Observed too frequent PING frames: %u PING frames within a last minute", cstate.get_received_ping_frame_count()); return Http2Error(Http2ErrorClass::HTTP2_ERROR_CLASS_CONNECTION, Http2ErrorCode::HTTP2_ERROR_ENHANCE_YOUR_CALM, @@ -897,6 +913,7 @@ rcv_continuation_frame(Http2ConnectionState &cstate, const Http2Frame &frame) // Set up the State Machine SCOPED_MUTEX_LOCK(stream_lock, stream->mutex, this_ethread()); + stream->mark_milestone(Http2StreamMilestone::START_TXN); stream->new_transaction(); // Send request header to SM stream->send_request(cstate); @@ -936,6 +953,7 @@ Http2ConnectionState::main_event_handler(int event, void *edata) case HTTP2_SESSION_EVENT_INIT: { ink_assert(this->ua_session == nullptr); this->ua_session = (Http2ClientSession *)edata; + REMEMBER(event, this->recursion); // [RFC 7540] 3.5. HTTP/2 Connection Preface. Upon establishment of a TCP connection and // determination that HTTP/2 will be used by both peers, each endpoint MUST @@ -961,6 +979,7 @@ Http2ConnectionState::main_event_handler(int event, void *edata) // Finalize HTTP/2 Connection case HTTP2_SESSION_EVENT_FINI: { SCOPED_MUTEX_LOCK(lock, this->mutex, this_ethread()); + REMEMBER(event, this->recursion); ink_assert(this->fini_received == false); this->fini_received = true; @@ -970,6 +989,7 @@ Http2ConnectionState::main_event_handler(int event, void *edata) } break; case HTTP2_SESSION_EVENT_XMIT: { + REMEMBER(event, this->recursion); SCOPED_MUTEX_LOCK(lock, this->mutex, this_ethread()); send_data_frames_depends_on_priority(); _scheduled = false; @@ -977,6 +997,7 @@ Http2ConnectionState::main_event_handler(int event, void *edata) // Parse received HTTP/2 frames case HTTP2_SESSION_EVENT_RECV: { + REMEMBER(event, this->recursion); const Http2Frame *frame = (Http2Frame *)edata; const Http2StreamId stream_id = frame->header().streamid; Http2Error error; @@ -999,8 +1020,8 @@ Http2ConnectionState::main_event_handler(int event, void *edata) const char *client_ip = ats_ip_ntop(ua_session->get_client_addr(), ipb, sizeof(ipb)); if (error.cls == Http2ErrorClass::HTTP2_ERROR_CLASS_CONNECTION) { if (error.msg) { - Error("HTTP/2 connection error client_ip=%s session_id=%" PRId64 " stream_id=%u %s", client_ip, - ua_session->connection_id(), stream_id, error.msg); + Error("HTTP/2 connection error code=0x%02x client_ip=%s session_id=%" PRId64 " stream_id=%u %s", + static_cast(error.code), client_ip, ua_session->connection_id(), stream_id, error.msg); } this->send_goaway_frame(this->latest_streamid_in, error.code); this->ua_session->set_half_close_local_flag(true); @@ -1012,8 +1033,8 @@ Http2ConnectionState::main_event_handler(int event, void *edata) // The Http2ClientSession will shutdown because connection_state.is_state_closed() will be true } else if (error.cls == Http2ErrorClass::HTTP2_ERROR_CLASS_STREAM) { if (error.msg) { - Error("HTTP/2 stream error client_ip=%s session_id=%" PRId64 " stream_id=%u %s", client_ip, ua_session->connection_id(), - stream_id, error.msg); + Error("HTTP/2 stream error code=0x%02x client_ip=%s session_id=%" PRId64 " stream_id=%u %s", static_cast(error.code), + client_ip, ua_session->connection_id(), stream_id, error.msg); } this->send_rst_stream_frame(stream_id, error.code); } @@ -1023,6 +1044,7 @@ Http2ConnectionState::main_event_handler(int event, void *edata) // Initiate a gracefull shutdown case HTTP2_SESSION_EVENT_SHUTDOWN_INIT: { + REMEMBER(event, this->recursion); ink_assert(shutdown_state == HTTP2_SHUTDOWN_NOT_INITIATED); shutdown_state = HTTP2_SHUTDOWN_INITIATED; // [RFC 7540] 6.8. GOAWAY @@ -1036,6 +1058,7 @@ Http2ConnectionState::main_event_handler(int event, void *edata) // Continue a gracefull shutdown case HTTP2_SESSION_EVENT_SHUTDOWN_CONT: { + REMEMBER(event, this->recursion); ink_assert(shutdown_state == HTTP2_SHUTDOWN_INITIATED); shutdown_cont_event = nullptr; shutdown_state = HTTP2_SHUTDOWN_IN_PROGRESS; @@ -1072,8 +1095,10 @@ Http2ConnectionState::main_event_handler(int event, void *edata) } int -Http2ConnectionState::state_closed(int /* event */, void *edata) +Http2ConnectionState::state_closed(int event, void *edata) { + REMEMBER(event, this->recursion); + if (edata == zombie_event) { // Zombie session is still around. Assert! ink_release_assert(zombie_event == nullptr); @@ -1257,6 +1282,7 @@ Http2ConnectionState::delete_stream(Http2Stream *stream) } Http2StreamDebug(ua_session, stream->get_id(), "Delete stream"); + REMEMBER(NO_EVENT, this->recursion); if (Http2::stream_priority_enabled) { Http2DependencyTree::Node *node = stream->priority_node; @@ -1298,6 +1324,8 @@ Http2ConnectionState::delete_stream(Http2Stream *stream) void Http2ConnectionState::release_stream(Http2Stream *stream) { + REMEMBER(NO_EVENT, this->recursion) + if (stream) { // Decrement total_client_streams_count here, because it's a counter include streams in the process of shutting down. // Other counters (client_streams_in_count/client_streams_out_count) are already decremented in delete_stream(). @@ -1545,6 +1573,8 @@ Http2ConnectionState::send_headers_frame(Http2Stream *stream) h2_hdr.destroy(); return; } + + stream->mark_milestone(Http2StreamMilestone::START_ENCODE_HEADERS); Http2ErrorCode result = http2_encode_header_blocks(&h2_hdr, buf, buf_len, &header_blocks_size, *(this->remote_hpack_handle), client_settings.get(HTTP2_SETTINGS_HEADER_TABLE_SIZE)); if (result != Http2ErrorCode::HTTP2_ERROR_NO_ERROR) { @@ -1561,6 +1591,7 @@ Http2ConnectionState::send_headers_frame(Http2Stream *stream) flags |= HTTP2_FLAGS_HEADERS_END_STREAM; stream->send_end_stream = true; } + stream->mark_milestone(Http2StreamMilestone::START_TX_HEADERS_FRAMES); } else { payload_length = BUFFER_SIZE_FOR_INDEX(buffer_size_index[HTTP2_FRAME_TYPE_HEADERS]); } @@ -1837,6 +1868,8 @@ Http2ConnectionState::send_ping_frame(Http2StreamId id, uint8_t flag, const uint void Http2ConnectionState::send_goaway_frame(Http2StreamId id, Http2ErrorCode ec) { + ink_assert(this->ua_session != nullptr); + Http2ConDebug(ua_session, "Send GOAWAY frame, last_stream_id: %d", id); if (ec != Http2ErrorCode::HTTP2_ERROR_NO_ERROR) { @@ -1846,8 +1879,6 @@ Http2ConnectionState::send_goaway_frame(Http2StreamId id, Http2ErrorCode ec) Http2Frame frame(HTTP2_FRAME_TYPE_GOAWAY, 0, 0); Http2Goaway goaway; - ink_assert(this->ua_session != nullptr); - goaway.last_streamid = id; goaway.error_code = ec; @@ -1976,6 +2007,7 @@ Http2ConnectionState::increment_client_rwnd(size_t amount) double sum = std::accumulate(this->_recent_rwnd_increment.begin(), this->_recent_rwnd_increment.end(), 0.0); double avg = sum / this->_recent_rwnd_increment.size(); if (avg < Http2::min_avg_window_update) { + HTTP2_INCREMENT_THREAD_DYN_STAT(HTTP2_STAT_INSUFFICIENT_AVG_WINDOW_UPDATE, this_ethread()); return Http2ErrorCode::HTTP2_ERROR_ENHANCE_YOUR_CALM; } return Http2ErrorCode::HTTP2_ERROR_NO_ERROR; diff --git a/proxy/http2/Http2ConnectionState.h b/proxy/http2/Http2ConnectionState.h index e6f4ff950b4..17726fc1231 100644 --- a/proxy/http2/Http2ConnectionState.h +++ b/proxy/http2/Http2ConnectionState.h @@ -132,7 +132,9 @@ class Http2ConnectionState : public Continuation { local_hpack_handle = new HpackHandle(HTTP2_HEADER_TABLE_SIZE); remote_hpack_handle = new HpackHandle(HTTP2_HEADER_TABLE_SIZE); - dependency_tree = new DependencyTree(Http2::max_concurrent_streams_in); + if (Http2::stream_priority_enabled) { + dependency_tree = new DependencyTree(Http2::max_concurrent_streams_in); + } } void @@ -140,6 +142,7 @@ class Http2ConnectionState : public Continuation { if (shutdown_cont_event) { shutdown_cont_event->cancel(); + shutdown_cont_event = nullptr; } cleanup_streams(); diff --git a/proxy/http2/Http2FrequencyCounter.cc b/proxy/http2/Http2FrequencyCounter.cc index dfe08b98507..9fab3e6acc6 100644 --- a/proxy/http2/Http2FrequencyCounter.cc +++ b/proxy/http2/Http2FrequencyCounter.cc @@ -26,7 +26,7 @@ void Http2FrequencyCounter::increment(uint16_t amount) { - ink_hrtime hrtime_sec = ink_hrtime_to_sec(Thread::get_hrtime()); + ink_hrtime hrtime_sec = this->_get_hrtime(); uint8_t counter_index = ((hrtime_sec % 60) >= 30); uint8_t last_index = ((this->_last_update % 60) >= 30); @@ -53,3 +53,9 @@ Http2FrequencyCounter::get_count() { return this->_count[0] + this->_count[1]; } + +ink_hrtime +Http2FrequencyCounter::_get_hrtime() +{ + return ink_hrtime_to_sec(Thread::get_hrtime()); +} diff --git a/proxy/http2/Http2FrequencyCounter.h b/proxy/http2/Http2FrequencyCounter.h index 9d2ed73b884..0b6de174afc 100644 --- a/proxy/http2/Http2FrequencyCounter.h +++ b/proxy/http2/Http2FrequencyCounter.h @@ -35,4 +35,7 @@ class Http2FrequencyCounter protected: uint16_t _count[2] = {0}; ink_hrtime _last_update = 0; + +private: + virtual ink_hrtime _get_hrtime(); }; diff --git a/proxy/http2/Http2Stream.cc b/proxy/http2/Http2Stream.cc index 5af0ef125c7..73d7a9301f7 100644 --- a/proxy/http2/Http2Stream.cc +++ b/proxy/http2/Http2Stream.cc @@ -28,6 +28,11 @@ #include +#define REMEMBER(e, r) \ + { \ + this->_history.push_back(MakeSourceLocation(), e, r); \ + } + #define Http2StreamDebug(fmt, ...) \ SsnDebug(parent, "http2_stream", "[%" PRId64 "] [%u] " fmt, parent->connection_id(), this->get_id(), ##__VA_ARGS__); @@ -37,6 +42,7 @@ int Http2Stream::main_event_handler(int event, void *edata) { SCOPED_MUTEX_LOCK(lock, this->mutex, this_ethread()); + REMEMBER(event, this->reentrancy_count); if (!this->_switch_thread_if_not_on_right_thread(event, edata)) { // Not on the right thread @@ -142,6 +148,9 @@ Http2Stream::decode_header_blocks(HpackHandle &hpack_handle, uint32_t maximum_ta void Http2Stream::send_request(Http2ConnectionState &cstate) { + ink_release_assert(this->current_reader != nullptr); + this->_http_sm_id = this->current_reader->sm_id; + // Convert header to HTTP/1.1 format http2_convert_header_from_2_to_1_1(&_req_header); @@ -325,6 +334,7 @@ Http2Stream::do_io_close(int /* flags */) super::release(nullptr); if (!closed) { + REMEMBER(NO_EVENT, this->reentrancy_count); Http2StreamDebug("do_io_close"); // When we get here, the SM has initiated the shutdown. Either it received a WRITE_COMPLETE, or it is shutting down. Any @@ -376,6 +386,8 @@ void Http2Stream::terminate_if_possible() { if (terminate_stream && reentrancy_count == 0) { + REMEMBER(NO_EVENT, this->reentrancy_count); + Http2ClientSession *h2_parent = static_cast(parent); SCOPED_MUTEX_LOCK(lock, h2_parent->connection_state.mutex, this_ethread()); h2_parent->connection_state.delete_stream(this); @@ -389,6 +401,7 @@ Http2Stream::initiating_close() { if (!closed) { SCOPED_MUTEX_LOCK(lock, this->mutex, this_ethread()); + REMEMBER(NO_EVENT, this->reentrancy_count); Http2StreamDebug("initiating_close"); // Set the state of the connection to closed @@ -457,6 +470,7 @@ Http2Stream::send_tracked_event(Event *event, int send_event, VIO *vio) } if (event == nullptr) { + REMEMBER(send_event, this->reentrancy_count); event = this_ethread()->schedule_imm(this, send_event, vio); } @@ -582,8 +596,8 @@ Http2Stream::update_write_request(IOBufferReader *buf_reader, int64_t write_len, // Still parsing the response_header int bytes_used = 0; int state = this->response_header.parse_resp(&http_parser, this->response_reader, &bytes_used, false); - // HTTPHdr::parse_resp() consumed the response_reader in above - write_vio.ndone += this->response_header.length_get(); + // HTTPHdr::parse_resp() consumed the response_reader in above (consumed size is `bytes_used`) + write_vio.ndone += bytes_used; switch (state) { case PARSE_RESULT_DONE: { @@ -616,6 +630,7 @@ Http2Stream::update_write_request(IOBufferReader *buf_reader, int64_t write_len, // make sure to send the end of stream is_done |= (write_vio.ntodo() + this->response_header.length_get()) == bytes_avail; if (this->response_is_data_available() || is_done) { + this->_milestones.mark(Http2StreamMilestone::START_TX_DATA_FRAMES); this->send_response_body(call_update); } break; @@ -627,6 +642,7 @@ Http2Stream::update_write_request(IOBufferReader *buf_reader, int64_t write_len, break; } } else { + this->_milestones.mark(Http2StreamMilestone::START_TX_DATA_FRAMES); this->send_response_body(call_update); } @@ -702,12 +718,15 @@ Http2Stream::reenable(VIO *vio) void Http2Stream::destroy() { + REMEMBER(NO_EVENT, this->reentrancy_count); Http2StreamDebug("Destroy stream, sent %" PRIu64 " bytes", this->bytes_sent); SCOPED_MUTEX_LOCK(lock, this->mutex, this_ethread()); // Clean up after yourself if this was an EOS ink_release_assert(this->closed); ink_release_assert(reentrancy_count == 0); + uint64_t cid = 0; + // Safe to initiate SSN_CLOSE if this is the last stream if (parent) { Http2ClientSession *h2_parent = static_cast(parent); @@ -718,14 +737,39 @@ Http2Stream::destroy() // Update session's stream counts, so it accurately goes into keep-alive state h2_parent->connection_state.release_stream(this); + cid = parent->connection_id(); } // Clean up the write VIO in case of inactivity timeout this->do_io_write(nullptr, 0, nullptr); HTTP2_DECREMENT_THREAD_DYN_STAT(HTTP2_STAT_CURRENT_CLIENT_STREAM_COUNT, _thread); - ink_hrtime end_time = Thread::get_hrtime(); - HTTP2_SUM_THREAD_DYN_STAT(HTTP2_STAT_TOTAL_TRANSACTIONS_TIME, _thread, end_time - _start_time); + + this->_milestones.mark(Http2StreamMilestone::CLOSE); + + ink_hrtime total_time = this->_milestones.elapsed(Http2StreamMilestone::OPEN, Http2StreamMilestone::CLOSE); + HTTP2_SUM_THREAD_DYN_STAT(HTTP2_STAT_TOTAL_TRANSACTIONS_TIME, this->_thread, total_time); + + // Slow Log + if (Http2::stream_slow_log_threshold != 0 && ink_hrtime_from_msec(Http2::stream_slow_log_threshold) < total_time) { + Error("[%" PRIu64 "] [%" PRIu32 "] [%" PRId64 "] Slow H2 Stream: " + "open: %" PRIu64 " " + "dec_hdrs: %.3f " + "txn: %.3f " + "enc_hdrs: %.3f " + "tx_hdrs: %.3f " + "tx_data: %.3f " + "close: %.3f", + cid, static_cast(this->_id), this->_http_sm_id, + ink_hrtime_to_msec(this->_milestones[Http2StreamMilestone::OPEN]), + this->_milestones.difference_sec(Http2StreamMilestone::OPEN, Http2StreamMilestone::START_DECODE_HEADERS), + this->_milestones.difference_sec(Http2StreamMilestone::OPEN, Http2StreamMilestone::START_TXN), + this->_milestones.difference_sec(Http2StreamMilestone::OPEN, Http2StreamMilestone::START_ENCODE_HEADERS), + this->_milestones.difference_sec(Http2StreamMilestone::OPEN, Http2StreamMilestone::START_TX_HEADERS_FRAMES), + this->_milestones.difference_sec(Http2StreamMilestone::OPEN, Http2StreamMilestone::START_TX_DATA_FRAMES), + this->_milestones.difference_sec(Http2StreamMilestone::OPEN, Http2StreamMilestone::CLOSE)); + } + _req_header.destroy(); response_header.destroy(); @@ -751,9 +795,8 @@ void Http2Stream::response_initialize_data_handling(bool &is_done) { is_done = false; - const char *name = "transfer-encoding"; - const char *value = "chunked"; - int chunked_index = response_header.value_get_index(name, strlen(name), value, strlen(value)); + int chunked_index = response_header.value_get_index(TS_MIME_FIELD_TRANSFER_ENCODING, TS_MIME_LEN_TRANSFER_ENCODING, + TS_HTTP_VALUE_CHUNKED, TS_HTTP_LEN_CHUNKED); // -1 means this value was not found for this field if (chunked_index >= 0) { Http2StreamDebug("Response is chunked"); @@ -935,6 +978,12 @@ Http2Stream::decrement_server_rwnd(size_t amount) } } +void +Http2Stream::mark_milestone(Http2StreamMilestone type) +{ + this->_milestones.mark(type); +} + bool Http2Stream::_switch_thread_if_not_on_right_thread(int event, void *edata) { diff --git a/proxy/http2/Http2Stream.h b/proxy/http2/Http2Stream.h index 3be1057a584..edb0116718c 100644 --- a/proxy/http2/Http2Stream.h +++ b/proxy/http2/Http2Stream.h @@ -28,12 +28,25 @@ #include "Http2DebugNames.h" #include "../http/HttpTunnel.h" // To get ChunkedHandler #include "Http2DependencyTree.h" +#include "tscore/History.h" +#include "Milestones.h" class Http2Stream; class Http2ConnectionState; typedef Http2DependencyTree::Tree DependencyTree; +enum class Http2StreamMilestone { + OPEN = 0, + START_DECODE_HEADERS, + START_TXN, + START_ENCODE_HEADERS, + START_TX_HEADERS_FRAMES, + START_TX_DATA_FRAMES, + CLOSE, + LAST_ENTRY, +}; + class Http2Stream : public ProxyClientTransaction { public: @@ -46,12 +59,15 @@ class Http2Stream : public ProxyClientTransaction void init(Http2StreamId sid, ssize_t initial_rwnd) { + this->mark_milestone(Http2StreamMilestone::OPEN); + _id = sid; - _start_time = Thread::get_hrtime(); _thread = this_ethread(); this->_client_rwnd = initial_rwnd; + HTTP2_INCREMENT_THREAD_DYN_STAT(HTTP2_STAT_CURRENT_CLIENT_STREAM_COUNT, _thread); HTTP2_INCREMENT_THREAD_DYN_STAT(HTTP2_STAT_TOTAL_CLIENT_STREAM_COUNT, _thread); + sm_reader = request_reader = request_buffer.alloc_reader(); http_parser_init(&http_parser); // FIXME: Are you sure? every "stream" needs request_header? @@ -222,6 +238,8 @@ class Http2Stream : public ProxyClientTransaction return is_first_transaction_flag; } + void mark_milestone(Http2StreamMilestone type); + private: void response_initialize_data_handling(bool &is_done); void response_process_data(bool &is_done); @@ -237,15 +255,18 @@ class Http2Stream : public ProxyClientTransaction bool _switch_thread_if_not_on_right_thread(int event, void *edata); HTTPParser http_parser; - ink_hrtime _start_time = 0; - EThread *_thread = nullptr; + EThread *_thread = nullptr; Http2StreamId _id; Http2StreamState _state = Http2StreamState::HTTP2_STREAM_STATE_IDLE; + int64_t _http_sm_id = -1; HTTPHdr _req_header; VIO read_vio; VIO write_vio; + History _history; + Milestones(Http2StreamMilestone::LAST_ENTRY)> _milestones; + bool trailing_header = false; bool chunked = false; diff --git a/proxy/http2/Makefile.am b/proxy/http2/Makefile.am index 7fe74800aeb..c0ae3abae05 100644 --- a/proxy/http2/Makefile.am +++ b/proxy/http2/Makefile.am @@ -50,9 +50,7 @@ libhttp2_a_SOURCES = \ Http2Stream.cc \ Http2Stream.h \ Http2SessionAccept.cc \ - Http2SessionAccept.h \ - HuffmanCodec.cc \ - HuffmanCodec.h + Http2SessionAccept.h if BUILD_TESTS libhttp2_a_SOURCES += \ @@ -60,26 +58,15 @@ libhttp2_a_SOURCES += \ endif check_PROGRAMS = \ - test_Huffmancode \ test_Http2DependencyTree \ test_Http2FrequencyCounter \ test_HPACK TESTS = \ - test_Huffmancode \ test_Http2DependencyTree \ test_Http2FrequencyCounter \ test_HPACK -test_Huffmancode_LDADD = \ - $(top_builddir)/src/tscore/libtscore.la \ - $(top_builddir)/src/tscpp/util/libtscpputil.la - -test_Huffmancode_SOURCES = \ - test_Huffmancode.cc \ - HuffmanCodec.cc \ - HuffmanCodec.h - test_Http2DependencyTree_LDADD = \ $(top_builddir)/src/tscore/libtscore.la \ $(top_builddir)/src/tscpp/util/libtscpputil.la @@ -117,8 +104,6 @@ test_HPACK_LDADD = \ test_HPACK_SOURCES = \ test_HPACK.cc \ - HuffmanCodec.cc \ - HuffmanCodec.h \ HPACK.cc \ HPACK.h diff --git a/proxy/http2/RegressionHPACK.cc b/proxy/http2/RegressionHPACK.cc index 7b2de58141a..8beb73d508c 100644 --- a/proxy/http2/RegressionHPACK.cc +++ b/proxy/http2/RegressionHPACK.cc @@ -41,37 +41,6 @@ const static int MAX_TABLE_SIZE = 4096; * * ***********************************************************************************/ -// [RFC 7541] C.1. Integer Representation Examples -const static struct { - uint32_t raw_integer; - uint8_t *encoded_field; - int encoded_field_len; - int prefix; -} integer_test_case[] = {{10, (uint8_t *)"\x0A", 1, 5}, {1337, (uint8_t *)"\x1F\x9A\x0A", 3, 5}, {42, (uint8_t *)"\x2A", 1, 8}}; - -// Example: custom-key: custom-header -const static struct { - char *raw_string; - uint32_t raw_string_len; - uint8_t *encoded_field; - int encoded_field_len; -} string_test_case[] = {{(char *)"", 0, - (uint8_t *)"\x0" - "", - 1}, - {(char *)"custom-key", 10, - (uint8_t *)"\xA" - "custom-key", - 11}, - {(char *)"", 0, - (uint8_t *)"\x80" - "", - 1}, - {(char *)"custom-key", 10, - (uint8_t *)"\x88" - "\x25\xa8\x49\xe9\x5b\xa9\x7d\x7f", - 9}}; - // [RFC 7541] C.2.4. Indexed Header Field const static struct { int index; @@ -317,42 +286,6 @@ const static struct { * * ***********************************************************************************/ -REGRESSION_TEST(HPACK_EncodeInteger)(RegressionTest *t, int, int *pstatus) -{ - TestBox box(t, pstatus); - box = REGRESSION_TEST_PASSED; - uint8_t buf[BUFSIZE_FOR_REGRESSION_TEST]; - - for (const auto &i : integer_test_case) { - memset(buf, 0, BUFSIZE_FOR_REGRESSION_TEST); - - int len = encode_integer(buf, buf + BUFSIZE_FOR_REGRESSION_TEST, i.raw_integer, i.prefix); - - box.check(len == i.encoded_field_len, "encoded length was %d, expecting %d", len, i.encoded_field_len); - box.check(len > 0 && memcmp(buf, i.encoded_field, len) == 0, "encoded value was invalid"); - } -} - -REGRESSION_TEST(HPACK_EncodeString)(RegressionTest *t, int, int *pstatus) -{ - TestBox box(t, pstatus); - box = REGRESSION_TEST_PASSED; - - uint8_t buf[BUFSIZE_FOR_REGRESSION_TEST]; - int len; - - // FIXME Current encoder support only huffman conding. - for (unsigned int i = 2; i < sizeof(string_test_case) / sizeof(string_test_case[0]); i++) { - memset(buf, 0, BUFSIZE_FOR_REGRESSION_TEST); - - len = encode_string(buf, buf + BUFSIZE_FOR_REGRESSION_TEST, string_test_case[i].raw_string, string_test_case[i].raw_string_len); - - box.check(len == string_test_case[i].encoded_field_len, "encoded length was %d, expecting %d", len, - string_test_case[i].encoded_field_len); - box.check(len > 0 && memcmp(buf, string_test_case[i].encoded_field, len) == 0, "encoded string was invalid"); - } -} - REGRESSION_TEST(HPACK_EncodeIndexedHeaderField)(RegressionTest *t, int, int *pstatus) { TestBox box(t, pstatus); @@ -466,41 +399,6 @@ REGRESSION_TEST(HPACK_Encode)(RegressionTest *t, int, int *pstatus) } } -REGRESSION_TEST(HPACK_DecodeInteger)(RegressionTest *t, int, int *pstatus) -{ - TestBox box(t, pstatus); - box = REGRESSION_TEST_PASSED; - - uint32_t actual; - - for (const auto &i : integer_test_case) { - int len = decode_integer(actual, i.encoded_field, i.encoded_field + i.encoded_field_len, i.prefix); - - box.check(len == i.encoded_field_len, "decoded length was %d, expecting %d", len, i.encoded_field_len); - box.check(actual == i.raw_integer, "decoded value was %d, expected %d", actual, i.raw_integer); - } -} - -REGRESSION_TEST(HPACK_DecodeString)(RegressionTest *t, int, int *pstatus) -{ - TestBox box(t, pstatus); - box = REGRESSION_TEST_PASSED; - - Arena arena; - char *actual = nullptr; - uint32_t actual_len = 0; - - hpack_huffman_init(); - - for (const auto &i : string_test_case) { - int len = decode_string(arena, &actual, actual_len, i.encoded_field, i.encoded_field + i.encoded_field_len); - - box.check(len == i.encoded_field_len, "decoded length was %d, expecting %d", len, i.encoded_field_len); - box.check(actual_len == i.raw_string_len, "length of decoded string was %d, expecting %d", actual_len, i.raw_string_len); - box.check(memcmp(actual, i.raw_string, actual_len) == 0, "decoded string was invalid"); - } -} - REGRESSION_TEST(HPACK_DecodeIndexedHeaderField)(RegressionTest *t, int, int *pstatus) { TestBox box(t, pstatus); diff --git a/proxy/http2/unit_tests/test_Http2FrequencyCounter.cc b/proxy/http2/unit_tests/test_Http2FrequencyCounter.cc index a1c0487420d..b69d58f1ef9 100644 --- a/proxy/http2/unit_tests/test_Http2FrequencyCounter.cc +++ b/proxy/http2/unit_tests/test_Http2FrequencyCounter.cc @@ -29,12 +29,22 @@ class TestHttp2FrequencyCounter : public Http2FrequencyCounter { public: void - set_internal_state(ink_hrtime last_update_sec, uint16_t count_0, uint16_t count_1) + set_internal_state(ink_hrtime now, ink_hrtime last_update_sec, uint16_t count_0, uint16_t count_1) { + this->_now = now; this->_last_update = last_update_sec; this->_count[0] = count_0; this->_count[1] = count_1; } + +private: + ink_hrtime + _get_hrtime() override + { + return this->_now; + } + + ink_hrtime _now = 0; }; TEST_CASE("Http2FrequencyCounter_basic", "[http2][Http2FrequencyCounter]") @@ -49,47 +59,45 @@ TEST_CASE("Http2FrequencyCounter_basic", "[http2][Http2FrequencyCounter]") counter.increment(2); REQUIRE(counter.get_count() == 3); - counter.set_internal_state(ink_hrtime_to_sec(Thread::get_hrtime()) - 10, 1, 2); + ink_hrtime now = ink_hrtime_to_sec(Thread::get_hrtime_updated()); + counter.set_internal_state(now, now - 10, 1, 2); REQUIRE(counter.get_count() == 3); } SECTION("Update at 0") { ink_hrtime now = ink_hrtime_to_sec(Thread::get_hrtime_updated()); - while (now % 60 != 0) { - sleep(1); - now = ink_hrtime_to_sec(Thread::get_hrtime_updated()); - } + now -= now % 60; - counter.set_internal_state(now - 5, 1, 2); + counter.set_internal_state(now, now - 5, 1, 2); counter.increment(); CHECK(counter.get_count() == 3); - counter.set_internal_state(now - 10, 1, 2); + counter.set_internal_state(now, now - 10, 1, 2); counter.increment(); CHECK(counter.get_count() == 3); - counter.set_internal_state(now - 20, 1, 2); + counter.set_internal_state(now, now - 20, 1, 2); counter.increment(); CHECK(counter.get_count() == 3); - counter.set_internal_state(now - 30, 1, 2); + counter.set_internal_state(now, now - 30, 1, 2); counter.increment(); CHECK(counter.get_count() == 3); - counter.set_internal_state(now - 40, 1, 2); + counter.set_internal_state(now, now - 40, 1, 2); counter.increment(); CHECK(counter.get_count() == 1); - counter.set_internal_state(now - 50, 1, 2); + counter.set_internal_state(now, now - 50, 1, 2); counter.increment(); CHECK(counter.get_count() == 1); - counter.set_internal_state(now - 60, 1, 2); + counter.set_internal_state(now, now - 60, 1, 2); counter.increment(); CHECK(counter.get_count() == 1); - counter.set_internal_state(now - 70, 1, 2); + counter.set_internal_state(now, now - 70, 1, 2); counter.increment(); CHECK(counter.get_count() == 1); } @@ -97,40 +105,38 @@ TEST_CASE("Http2FrequencyCounter_basic", "[http2][Http2FrequencyCounter]") SECTION("Update at 10") { ink_hrtime now = ink_hrtime_to_sec(Thread::get_hrtime_updated()); - while (now % 60 != 10) { - sleep(1); - now = ink_hrtime_to_sec(Thread::get_hrtime_updated()); - } + now -= now % 60; + now += 10; - counter.set_internal_state(now - 5, 1, 2); + counter.set_internal_state(now, now - 5, 1, 2); counter.increment(); CHECK(counter.get_count() == 4); - counter.set_internal_state(now - 10, 1, 2); + counter.set_internal_state(now, now - 10, 1, 2); counter.increment(); CHECK(counter.get_count() == 4); - counter.set_internal_state(now - 20, 1, 2); + counter.set_internal_state(now, now - 20, 1, 2); counter.increment(); CHECK(counter.get_count() == 3); - counter.set_internal_state(now - 30, 1, 2); + counter.set_internal_state(now, now - 30, 1, 2); counter.increment(); CHECK(counter.get_count() == 3); - counter.set_internal_state(now - 40, 1, 2); + counter.set_internal_state(now, now - 40, 1, 2); counter.increment(); CHECK(counter.get_count() == 3); - counter.set_internal_state(now - 50, 1, 2); + counter.set_internal_state(now, now - 50, 1, 2); counter.increment(); CHECK(counter.get_count() == 1); - counter.set_internal_state(now - 60, 1, 2); + counter.set_internal_state(now, now - 60, 1, 2); counter.increment(); CHECK(counter.get_count() == 1); - counter.set_internal_state(now - 70, 1, 2); + counter.set_internal_state(now, now - 70, 1, 2); counter.increment(); CHECK(counter.get_count() == 1); } @@ -138,40 +144,38 @@ TEST_CASE("Http2FrequencyCounter_basic", "[http2][Http2FrequencyCounter]") SECTION("Update at 30") { ink_hrtime now = ink_hrtime_to_sec(Thread::get_hrtime_updated()); - while (now % 60 != 30) { - sleep(1); - now = ink_hrtime_to_sec(Thread::get_hrtime_updated()); - } + now -= now % 60; + now += 30; - counter.set_internal_state(now - 5, 1, 2); + counter.set_internal_state(now, now - 5, 1, 2); counter.increment(); CHECK(counter.get_count() == 2); - counter.set_internal_state(now - 10, 1, 2); + counter.set_internal_state(now, now - 10, 1, 2); counter.increment(); CHECK(counter.get_count() == 2); - counter.set_internal_state(now - 20, 1, 2); + counter.set_internal_state(now, now - 20, 1, 2); counter.increment(); CHECK(counter.get_count() == 2); - counter.set_internal_state(now - 30, 1, 2); + counter.set_internal_state(now, now - 30, 1, 2); counter.increment(); CHECK(counter.get_count() == 2); - counter.set_internal_state(now - 40, 1, 2); + counter.set_internal_state(now, now - 40, 1, 2); counter.increment(); CHECK(counter.get_count() == 1); - counter.set_internal_state(now - 50, 1, 2); + counter.set_internal_state(now, now - 50, 1, 2); counter.increment(); CHECK(counter.get_count() == 1); - counter.set_internal_state(now - 60, 1, 2); + counter.set_internal_state(now, now - 60, 1, 2); counter.increment(); CHECK(counter.get_count() == 1); - counter.set_internal_state(now - 70, 1, 2); + counter.set_internal_state(now, now - 70, 1, 2); counter.increment(); CHECK(counter.get_count() == 1); } @@ -179,40 +183,38 @@ TEST_CASE("Http2FrequencyCounter_basic", "[http2][Http2FrequencyCounter]") SECTION("Update at 40") { ink_hrtime now = ink_hrtime_to_sec(Thread::get_hrtime_updated()); - while (now % 60 != 40) { - sleep(1); - now = ink_hrtime_to_sec(Thread::get_hrtime_updated()); - } + now -= now % 60; + now += 40; - counter.set_internal_state(now - 5, 1, 2); + counter.set_internal_state(now, now - 5, 1, 2); counter.increment(); CHECK(counter.get_count() == 4); - counter.set_internal_state(now - 10, 1, 2); + counter.set_internal_state(now, now - 10, 1, 2); counter.increment(); CHECK(counter.get_count() == 4); - counter.set_internal_state(now - 20, 1, 2); + counter.set_internal_state(now, now - 20, 1, 2); counter.increment(); CHECK(counter.get_count() == 2); - counter.set_internal_state(now - 30, 1, 2); + counter.set_internal_state(now, now - 30, 1, 2); counter.increment(); CHECK(counter.get_count() == 2); - counter.set_internal_state(now - 40, 1, 2); + counter.set_internal_state(now, now - 40, 1, 2); counter.increment(); CHECK(counter.get_count() == 2); - counter.set_internal_state(now - 50, 1, 2); + counter.set_internal_state(now, now - 50, 1, 2); counter.increment(); CHECK(counter.get_count() == 1); - counter.set_internal_state(now - 60, 1, 2); + counter.set_internal_state(now, now - 60, 1, 2); counter.increment(); CHECK(counter.get_count() == 1); - counter.set_internal_state(now - 70, 1, 2); + counter.set_internal_state(now, now - 70, 1, 2); counter.increment(); CHECK(counter.get_count() == 1); }