diff --git a/CHANGELOG.md b/CHANGELOG.md index 488c3f9a5..cf7eeddac 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -2,8 +2,13 @@ ## Unreleased +**Features**: + +- Report the byte size of discarded logs and metrics in client reports under the `log_byte` and `trace_metric_byte` categories, alongside the existing `log_item` and `trace_metric` counts. + **Fixes**: - Honor checks before launching crash reporter ([#1906](https://github.com/getsentry/sentry-native/pull/1906)) +- Client reports now count every log in a discarded batch instead of counting the whole envelope item as a single discard, so dropping a batch of 100 logs is reported as 100 discarded `log_item`s rather than 1. The same applies to batched metrics. ## 0.16.0 diff --git a/src/sentry_batcher.c b/src/sentry_batcher.c index 4572ab666..c01d2309f 100644 --- a/src/sentry_batcher.c +++ b/src/sentry_batcher.c @@ -3,6 +3,7 @@ #include "sentry_cpu_relax.h" #include "sentry_options.h" #include "sentry_utils.h" +#include "sentry_value.h" // The batcher thread sleeps for this interval between flush cycles. // When the timer fires and there are items in the buffer, they are flushed @@ -311,8 +312,9 @@ sentry__batcher_enqueue(sentry_batcher_t *batcher, sentry_value_t item) || sentry__atomic_fetch(&batcher->active_idx) != active_idx) { continue; } - sentry__client_report_discard( - SENTRY_DISCARD_REASON_QUEUE_OVERFLOW, batcher->data_category, 1); + sentry__client_report_discard_with_bytes( + SENTRY_DISCARD_REASON_QUEUE_OVERFLOW, batcher->data_category, 1, + (long)sentry__value_estimate_serialized_size(item)); return false; } } diff --git a/src/sentry_client_report.c b/src/sentry_client_report.c index 2c553b9d8..a3c375327 100644 --- a/src/sentry_client_report.c +++ b/src/sentry_client_report.c @@ -19,6 +19,27 @@ sentry__client_report_discard(sentry_discard_reason_t reason, (long *)&g_discard_counts[reason][category], quantity); } +void +sentry__client_report_discard_with_bytes(sentry_discard_reason_t reason, + sentry_data_category_t category, long quantity, long bytes) +{ + sentry__client_report_discard(reason, category, quantity); + + switch (category) { + case SENTRY_DATA_CATEGORY_LOG_ITEM: + sentry__client_report_discard( + reason, SENTRY_DATA_CATEGORY_LOG_BYTE, bytes); + break; + case SENTRY_DATA_CATEGORY_TRACE_METRIC: + sentry__client_report_discard( + reason, SENTRY_DATA_CATEGORY_TRACE_METRIC_BYTE, bytes); + break; + default: + // all other categories have no byte counterpart + break; + } +} + bool sentry__client_report_has_pending(void) { diff --git a/src/sentry_client_report.h b/src/sentry_client_report.h index eec84e248..ff30e09a5 100644 --- a/src/sentry_client_report.h +++ b/src/sentry_client_report.h @@ -22,6 +22,10 @@ typedef enum { * Data categories for tracking discarded events. * These match the rate limiting categories defined at: * https://develop.sentry.dev/sdk/expected-features/rate-limiting/#definitions + * + * The `_BYTE` categories track the byte size of discarded telemetry alongside + * its item count, see + * https://develop.sentry.dev/sdk/telemetry/client-reports/#log-byte-outcomes */ typedef enum { SENTRY_DATA_CATEGORY_ERROR, @@ -32,11 +36,17 @@ typedef enum { SENTRY_DATA_CATEGORY_FEEDBACK, SENTRY_DATA_CATEGORY_TRACE_METRIC, SENTRY_DATA_CATEGORY_REPLAY, + SENTRY_DATA_CATEGORY_LOG_BYTE, + SENTRY_DATA_CATEGORY_TRACE_METRIC_BYTE, SENTRY_DATA_CATEGORY_MAX } sentry_data_category_t; /** * Consumed discard counts, used to restore them on send failure. + * + * NOTE: `long` is 32-bit on Windows, so the `_BYTE` categories saturate at 2GiB + * of discarded telemetry between two client reports. Since the counters are + * flushed with every outgoing envelope, reaching that is not realistic. */ typedef struct { long counts[SENTRY_DISCARD_REASON_MAX][SENTRY_DATA_CATEGORY_MAX]; @@ -49,6 +59,16 @@ typedef struct { void sentry__client_report_discard(sentry_discard_reason_t reason, sentry_data_category_t category, long quantity); +/** + * Record `quantity` discarded items of `category`, plus `bytes` under the + * category's byte counterpart (`log_byte` for logs, `trace_metric_byte` for + * metrics). `bytes` is ignored for categories that have no byte counterpart, + * so callers that discard items of an unknown category can use this + * unconditionally. + */ +void sentry__client_report_discard_with_bytes(sentry_discard_reason_t reason, + sentry_data_category_t category, long quantity, long bytes); + /** * Check if there are any pending discards to report. */ diff --git a/src/sentry_envelope.c b/src/sentry_envelope.c index ff2279f20..ae2f8f0d8 100644 --- a/src/sentry_envelope.c +++ b/src/sentry_envelope.c @@ -169,6 +169,29 @@ item_type_to_data_category(const char *ty) return SENTRY_DATA_CATEGORY_ERROR; } +/** + * Records a client report discard for a single envelope item. + * + * Batched items (logs, metrics) carry more than one item in a single payload, + * so the count comes from their `item_count` header. The already-serialized + * payload gives us an exact byte size for the `*_byte` categories. + */ +static void +discard_envelope_item( + const sentry_envelope_item_t *item, sentry_discard_reason_t reason) +{ + const char *ty = sentry_value_as_string( + sentry_value_get_by_key(item->headers, "type")); + const sentry_value_t item_count + = sentry_value_get_by_key(item->headers, "item_count"); + const long quantity = sentry_value_is_null(item_count) + ? 1 + : (long)sentry_value_as_int32(item_count); + + sentry__client_report_discard_with_bytes(reason, + item_type_to_data_category(ty), quantity, (long)item->payload_len); +} + bool sentry__envelope_can_add_client_report( const sentry_envelope_t *envelope, const sentry_rate_limiter_t *rl) @@ -869,11 +892,8 @@ sentry_envelope_serialize_ratelimited(const sentry_envelope_t *envelope, // category < 0 means the item should bypass rate limiting if (category >= 0 && sentry__rate_limiter_is_disabled(rl, category)) { - const char *ty = sentry_value_as_string( - sentry_value_get_by_key(item->headers, "type")); - sentry__client_report_discard( - SENTRY_DISCARD_REASON_RATELIMIT_BACKOFF, - item_type_to_data_category(ty), 1); + discard_envelope_item( + item, SENTRY_DISCARD_REASON_RATELIMIT_BACKOFF); continue; } } @@ -1349,6 +1369,10 @@ data_category_to_string(sentry_data_category_t category) return "trace_metric"; case SENTRY_DATA_CATEGORY_REPLAY: return "replay"; + case SENTRY_DATA_CATEGORY_LOG_BYTE: + return "log_byte"; + case SENTRY_DATA_CATEGORY_TRACE_METRIC_BYTE: + return "trace_metric_byte"; case SENTRY_DATA_CATEGORY_MAX: default: return "unknown"; @@ -1425,10 +1449,7 @@ sentry__envelope_discard(const sentry_envelope_t *envelope, if (rl && sentry__rate_limiter_is_disabled(rl, category)) { continue; } - const char *ty = sentry_value_as_string( - sentry_value_get_by_key(item->headers, "type")); - sentry__client_report_discard( - reason, item_type_to_data_category(ty), 1); + discard_envelope_item(item, reason); } } diff --git a/src/sentry_logs.c b/src/sentry_logs.c index 7c5991682..cc5024852 100644 --- a/src/sentry_logs.c +++ b/src/sentry_logs.c @@ -487,12 +487,17 @@ send_log(sentry_level_t level, sentry_value_t log) bool discarded = false; SENTRY_WITH_OPTIONS (options) { if (options->before_send_log_func) { + // the hook takes ownership and decrefs the log when it discards it, + // so we have to size it up front for the `log_byte` client report + const size_t log_bytes + = sentry__value_estimate_serialized_size(log); log = options->before_send_log_func( log, options->before_send_log_data); if (sentry_value_is_null(log)) { SENTRY_DEBUG("log was discarded by the `before_send_log` hook"); - sentry__client_report_discard(SENTRY_DISCARD_REASON_BEFORE_SEND, - SENTRY_DATA_CATEGORY_LOG_ITEM, 1); + sentry__client_report_discard_with_bytes( + SENTRY_DISCARD_REASON_BEFORE_SEND, + SENTRY_DATA_CATEGORY_LOG_ITEM, 1, (long)log_bytes); discarded = true; } } diff --git a/src/sentry_metrics.c b/src/sentry_metrics.c index 033af6b46..6c2413af4 100644 --- a/src/sentry_metrics.c +++ b/src/sentry_metrics.c @@ -77,14 +77,20 @@ sentry_scope_capture_metric(sentry_scope_t *scope, sentry_metric_type_t type, sentry__scope_free_one_shot(scope); SENTRY_WITH_OPTIONS (options) { if (options->before_send_metric_func) { + // the hook takes ownership and decrefs the metric when it + // discards it, so we have to size it up front for the + // `trace_metric_byte` client report + const size_t metric_bytes + = sentry__value_estimate_serialized_size(metric); metric = options->before_send_metric_func( metric, options->before_send_metric_data); if (sentry_value_is_null(metric)) { SENTRY_DEBUG("metric was discarded by the " "`before_send_metric` hook"); - sentry__client_report_discard( + sentry__client_report_discard_with_bytes( SENTRY_DISCARD_REASON_BEFORE_SEND, - SENTRY_DATA_CATEGORY_TRACE_METRIC, 1); + SENTRY_DATA_CATEGORY_TRACE_METRIC, 1, + (long)metric_bytes); discarded = true; } } diff --git a/src/sentry_value.c b/src/sentry_value.c index 11d74481f..54a8c4d30 100644 --- a/src/sentry_value.c +++ b/src/sentry_value.c @@ -1158,6 +1158,45 @@ sentry__value_foreach_key_value(sentry_value_t value, } } +size_t +sentry__value_estimate_serialized_size(sentry_value_t value) +{ + const thing_t *thing = value_as_thing(value); + if (!thing) { + if ((value._bits & TAG_MASK) == TAG_INT32) { + return 11; // upper bound, as in `-2147483648` + } + return value._bits == CONST_FALSE ? 5 : 4; // `false`, `true`, `null` + } + switch (thing_get_type(thing)) { + case THING_TYPE_LIST: { + const list_t *l = thing->payload._ptr; + size_t size = 2; // [] + for (size_t i = 0; i < l->len; i++) { + size += sentry__value_estimate_serialized_size(l->items[i]); + } + return l->len ? size + l->len - 1 : size; // separating commas + } + case THING_TYPE_OBJECT: { + const obj_t *o = thing->payload._ptr; + size_t size = 2; // {} + for (size_t i = 0; i < o->len; i++) { + size += strlen(o->pairs[i].k) + 3; // "key": + size += sentry__value_estimate_serialized_size(o->pairs[i].v); + } + return o->len ? size + o->len - 1 : size; // separating commas + } + case THING_TYPE_STRING: + return strlen(thing->payload._ptr) + 2; // surrounding quotes + case THING_TYPE_DOUBLE: + case THING_TYPE_INT64: + case THING_TYPE_UINT64: + default: + // upper bound for any 64-bit integer or double rendering + return 24; + } +} + sentry_value_t sentry_value_get_by_index_owned(sentry_value_t value, size_t index) { diff --git a/src/sentry_value.h b/src/sentry_value.h index ec90c1d95..848ad1250 100644 --- a/src/sentry_value.h +++ b/src/sentry_value.h @@ -67,6 +67,16 @@ sentry_value_t sentry__value_new_list_with_size(size_t size); */ sentry_value_t sentry__value_new_object_with_size(size_t size); +/** + * Estimates the size in bytes of `value`s JSON representation. + * + * This walks the value without allocating and does not account for string + * escaping or the exact rendering of numbers, so the result is an + * approximation. It is used for the `*_byte` client report categories, which + * explicitly allow one. + */ +size_t sentry__value_estimate_serialized_size(sentry_value_t value); + /** * Iterates over the key/value pairs of an object value. The callback receives a * borrowed reference for each value. Does nothing if `value` is not an object. diff --git a/tests/test_integration_client_reports.py b/tests/test_integration_client_reports.py index f0d17232e..4cc48c280 100644 --- a/tests/test_integration_client_reports.py +++ b/tests/test_integration_client_reports.py @@ -193,9 +193,14 @@ def test_client_report_before_send_log(cmake, httpserver): envelope = Envelope.deserialize(httpserver.log[0][0].get_data()) assert_event(envelope) + # the discarded log is reported both as an item count and as a byte size, + # see https://develop.sentry.dev/sdk/telemetry/client-reports/#log-byte-outcomes assert_client_report( envelope, - [{"reason": "before_send", "category": "log_item", "quantity": 1}], + [ + {"reason": "before_send", "category": "log_item", "quantity": 1}, + {"reason": "before_send", "category": "log_byte"}, + ], ) @@ -226,7 +231,10 @@ def test_client_report_before_send_metric(cmake, httpserver): assert_event(envelope) assert_client_report( envelope, - [{"reason": "before_send", "category": "trace_metric", "quantity": 1}], + [ + {"reason": "before_send", "category": "trace_metric", "quantity": 1}, + {"reason": "before_send", "category": "trace_metric_byte"}, + ], ) diff --git a/tests/unit/test_client_report.c b/tests/unit/test_client_report.c index e97b90901..7ae7ef640 100644 --- a/tests/unit/test_client_report.c +++ b/tests/unit/test_client_report.c @@ -179,7 +179,8 @@ SENTRY_TEST(client_report_discard_envelope) sentry_value_t discarded = sentry_value_get_by_key(value, "discarded_events"); - TEST_CHECK_INT_EQUAL(sentry_value_get_length(discarded), 7); + // 7 item categories, plus a byte counterpart for `log` and `trace_metric` + TEST_CHECK_INT_EQUAL(sentry_value_get_length(discarded), 9); sentry_value_t entry0 = sentry_value_get_by_index(discarded, 0); TEST_CHECK_STRING_EQUAL( @@ -251,7 +252,104 @@ SENTRY_TEST(client_report_discard_envelope) TEST_CHECK_INT_EQUAL( sentry_value_as_int32(sentry_value_get_by_key(entry6, "quantity")), 1); + // the byte categories are the size of the serialized payload, which is + // `{}` for every item added above + sentry_value_t entry7 = sentry_value_get_by_index(discarded, 7); + TEST_CHECK_STRING_EQUAL( + sentry_value_as_string(sentry_value_get_by_key(entry7, "reason")), + "network_error"); + TEST_CHECK_STRING_EQUAL( + sentry_value_as_string(sentry_value_get_by_key(entry7, "category")), + "log_byte"); + TEST_CHECK_INT_EQUAL( + sentry_value_as_int32(sentry_value_get_by_key(entry7, "quantity")), 2); + + sentry_value_t entry8 = sentry_value_get_by_index(discarded, 8); + TEST_CHECK_STRING_EQUAL( + sentry_value_as_string(sentry_value_get_by_key(entry8, "reason")), + "network_error"); + TEST_CHECK_STRING_EQUAL( + sentry_value_as_string(sentry_value_get_by_key(entry8, "category")), + "trace_metric_byte"); + TEST_CHECK_INT_EQUAL( + sentry_value_as_int32(sentry_value_get_by_key(entry8, "quantity")), 2); + + sentry_value_decref(value); + sentry_envelope_free(carrier); + sentry_envelope_free(envelope); + sentry_close(); +} + +SENTRY_TEST(client_report_discard_batched_logs) +{ + SENTRY_TEST_OPTIONS_NEW(options); + sentry_init(options); + + TEST_CHECK(!sentry__client_report_has_pending()); + + // A `log` envelope item carries a whole batch of logs, so the discard has + // to be counted per log and not per item. + sentry_value_t logs = sentry_value_new_object(); + sentry_value_t items = sentry_value_new_list(); + for (int i = 0; i < 4; i++) { + sentry_value_t log = sentry_value_new_object(); + sentry_value_set_by_key( + log, "body", sentry_value_new_string("some log body")); + sentry_value_append(items, log); + } + sentry_value_set_by_key(logs, "items", items); + + sentry_envelope_t *envelope = sentry__envelope_new(); + sentry_envelope_item_t *log_item + = sentry__envelope_add_logs(envelope, logs); + TEST_CHECK(!!log_item); + TEST_CHECK_INT_EQUAL(sentry_value_as_int32(sentry__envelope_item_get_header( + log_item, "item_count")), + 4); + + size_t log_payload_len = 0; + TEST_CHECK(!!sentry__envelope_item_get_payload(log_item, &log_payload_len)); + + sentry__envelope_discard(envelope, SENTRY_DISCARD_REASON_SEND_ERROR, NULL); + + sentry_client_report_t report; + TEST_CHECK(sentry__client_report_save(&report)); + sentry_envelope_t *carrier = sentry__envelope_new(); + sentry_envelope_item_t *item + = sentry__envelope_add_client_report(carrier, &report); + TEST_CHECK(!!item); + + size_t payload_len = 0; + const char *payload = sentry__envelope_item_get_payload(item, &payload_len); + sentry_value_t value = sentry__value_from_json(payload, payload_len); + + sentry_value_t discarded + = sentry_value_get_by_key(value, "discarded_events"); + TEST_CHECK_INT_EQUAL(sentry_value_get_length(discarded), 2); + + sentry_value_t entry0 = sentry_value_get_by_index(discarded, 0); + TEST_CHECK_STRING_EQUAL( + sentry_value_as_string(sentry_value_get_by_key(entry0, "reason")), + "send_error"); + TEST_CHECK_STRING_EQUAL( + sentry_value_as_string(sentry_value_get_by_key(entry0, "category")), + "log_item"); + TEST_CHECK_INT_EQUAL( + sentry_value_as_int32(sentry_value_get_by_key(entry0, "quantity")), 4); + + sentry_value_t entry1 = sentry_value_get_by_index(discarded, 1); + TEST_CHECK_STRING_EQUAL( + sentry_value_as_string(sentry_value_get_by_key(entry1, "reason")), + "send_error"); + TEST_CHECK_STRING_EQUAL( + sentry_value_as_string(sentry_value_get_by_key(entry1, "category")), + "log_byte"); + TEST_CHECK_INT_EQUAL( + sentry_value_as_int32(sentry_value_get_by_key(entry1, "quantity")), + (int32_t)log_payload_len); + sentry_value_decref(value); + sentry_value_decref(logs); sentry_envelope_free(carrier); sentry_envelope_free(envelope); sentry_close(); @@ -421,7 +519,7 @@ SENTRY_TEST(client_report_queue_overflow) sentry_value_t discarded = sentry_value_get_by_key(value, "discarded_events"); - TEST_CHECK_INT_EQUAL(sentry_value_get_length(discarded), 1); + TEST_CHECK_INT_EQUAL(sentry_value_get_length(discarded), 2); sentry_value_t entry0 = sentry_value_get_by_index(discarded, 0); TEST_CHECK_STRING_EQUAL( @@ -433,6 +531,16 @@ SENTRY_TEST(client_report_queue_overflow) TEST_CHECK_INT_EQUAL( sentry_value_as_int32(sentry_value_get_by_key(entry0, "quantity")), 1); + sentry_value_t entry1 = sentry_value_get_by_index(discarded, 1); + TEST_CHECK_STRING_EQUAL( + sentry_value_as_string(sentry_value_get_by_key(entry1, "reason")), + "queue_overflow"); + TEST_CHECK_STRING_EQUAL( + sentry_value_as_string(sentry_value_get_by_key(entry1, "category")), + "log_byte"); + TEST_CHECK( + sentry_value_as_int32(sentry_value_get_by_key(entry1, "quantity")) > 0); + sentry_value_decref(value); sentry_envelope_free(envelope); sentry__batcher_release(batcher); diff --git a/tests/unit/test_value.c b/tests/unit/test_value.c index 04e08310b..86887852a 100644 --- a/tests/unit/test_value.c +++ b/tests/unit/test_value.c @@ -1221,6 +1221,59 @@ SENTRY_TEST(value_json_len_out) sentry_free(json); } +static size_t +actual_json_size(sentry_value_t value) +{ + size_t json_len = 0; + char *json = sentry__value_to_json(value, &json_len); + sentry_free(json); + return json_len; +} + +SENTRY_TEST(value_estimate_serialized_size) +{ + // for values made up of only strings and containers the estimate is exact + sentry_value_t obj = sentry_value_new_object(); + TEST_CHECK_INT_EQUAL( + sentry__value_estimate_serialized_size(obj), actual_json_size(obj)); + + sentry_value_set_by_key(obj, "body", sentry_value_new_string("hello")); + TEST_CHECK_INT_EQUAL( + sentry__value_estimate_serialized_size(obj), actual_json_size(obj)); + + sentry_value_t list = sentry_value_new_list(); + sentry_value_append(list, sentry_value_new_string("ab")); + sentry_value_append(list, sentry_value_new_string("cd")); + TEST_CHECK_INT_EQUAL( + sentry__value_estimate_serialized_size(list), actual_json_size(list)); + + sentry_value_set_by_key(obj, "attributes", list); + TEST_CHECK_INT_EQUAL( + sentry__value_estimate_serialized_size(obj), actual_json_size(obj)); + + // booleans and null are exact too + sentry_value_t exact[] = { sentry_value_new_null(), + sentry_value_new_bool(true), sentry_value_new_bool(false) }; + for (size_t i = 0; i < sizeof(exact) / sizeof(exact[0]); i++) { + TEST_CHECK_INT_EQUAL(sentry__value_estimate_serialized_size(exact[i]), + actual_json_size(exact[i])); + } + + // numbers are estimated with an upper bound + TEST_CHECK(sentry__value_estimate_serialized_size( + sentry_value_new_int32(INT32_MIN)) + >= actual_json_size(sentry_value_new_int32(INT32_MIN))); + + sentry_value_set_by_key(obj, "count", sentry_value_new_int32(42)); + sentry_value_set_by_key(obj, "ratio", sentry_value_new_double(0.5)); + sentry_value_set_by_key(obj, "flag", sentry_value_new_bool(true)); + sentry_value_set_by_key(obj, "nothing", sentry_value_new_null()); + TEST_CHECK( + sentry__value_estimate_serialized_size(obj) >= actual_json_size(obj)); + + sentry_value_decref(obj); +} + SENTRY_TEST(value_json_escaping) { sentry_value_t rv = sentry__value_from_json( diff --git a/tests/unit/tests.inc b/tests/unit/tests.inc index 6789e1d92..c4f728d9e 100644 --- a/tests/unit/tests.inc +++ b/tests/unit/tests.inc @@ -90,6 +90,7 @@ XX(clear_options) XX(client_report_cache_overflow) XX(client_report_concurrent) XX(client_report_discard) +XX(client_report_discard_batched_logs) XX(client_report_discard_envelope) XX(client_report_discard_rate_limited) XX(client_report_discard_raw_envelope) @@ -425,6 +426,7 @@ XX(value_clone_nested_modify_middle) XX(value_clone_object) XX(value_clone_of_clone) XX(value_double) +XX(value_estimate_serialized_size) XX(value_foreach_key_value) XX(value_freezing) XX(value_from_msgpack_bool)