From 0e8df1c7e48bcae2285c7c138bd50f932049bd24 Mon Sep 17 00:00:00 2001 From: Neels Hofmeyr Date: Mon, 11 Feb 2019 20:32:25 +0100 Subject: add osmo_use_count API Provide a common implementation of use counting that supports naming each user as well as counting more than just one use per user, depending on the rules the caller implies. In osmo-msc, we were originally using a simple int counter to see whether a connection is still in use or should be discarded. For clarity, we later added names to each user in the form of a bitmask of flags, to figure out exactly which users are still active: for logging and to debug double get / double put bugs. This however is still not adequate, since there may be more than one CM Service Request pending. Also, it is a specialized implementation that is not re-usable. With this generalized implementation, we can: - fix the problem of inadequate counting of multiple concurrent CM Service Requests (more than one use count per user category), - directly use arbitrary names for uses like __func__ or "foo" (no need to define enums and value_string[]s), - re-use the same code for e.g. vlr_subscr and get fairly detailed VLR susbscriber usage logging for free. Change-Id: Ife31e6798b4e728a23913179e346552a7dd338c0 --- tests/use_count/use_count_test.c | 339 +++++++++++++++++++++++++++++++++++++ tests/use_count/use_count_test.err | 171 +++++++++++++++++++ tests/use_count/use_count_test.ok | 0 3 files changed, 510 insertions(+) create mode 100644 tests/use_count/use_count_test.c create mode 100644 tests/use_count/use_count_test.err create mode 100644 tests/use_count/use_count_test.ok (limited to 'tests/use_count') diff --git a/tests/use_count/use_count_test.c b/tests/use_count/use_count_test.c new file mode 100644 index 00000000..0b081c9c --- /dev/null +++ b/tests/use_count/use_count_test.c @@ -0,0 +1,339 @@ +/* Test implementation for osmo_use_count API. */ +/* + * (C) 2019 by sysmocom s.f.m.c. GmbH + * + * All Rights Reserved + * + * Author: Neels Hofmeyr + * + * SPDX-License-Identifier: GPL-2.0+ + * + * This program is free software; you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation; either version 2 of the License, or + * (at your option) any later version. + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License along + * with this program; if not, write to the Free Software Foundation, Inc., + * 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA. + */ + +#include +#include +#include +#include + +#include +#include +#include + +#include + +static void *ctx = NULL; + +#define log(fmt, args...) fprintf(stderr, fmt, ##args) + +enum { + DFOO, +}; + +#define FOO_USE_BARRING "barring" +#define FOO_USE_FIGHTING "fighting" +#define FOO_USE_KUNG "kungfoo" +#define FOO_USE_RELEASING "releasing" + +LLIST_HEAD(all_foo); + +struct foo { + struct llist_head entry; + struct osmo_fsm_inst *fi; + struct osmo_use_count use_count; + struct osmo_use_count_entry use_count_buf[10]; +}; + +enum foo_fsm_events { + FOO_EV_UNUSED, +}; + +static char name_buf[1024]; +#define use_count_name(UL) osmo_use_count_name_buf(name_buf, sizeof(name_buf), UL) + +int foo_use_cb(struct osmo_use_count_entry *use_count_entry, int32_t old_use_count, + const char *file, int line) +{ + struct osmo_use_count *use_count = use_count_entry->use_count; + struct foo *foo = use_count->talloc_object; + const char *use = use_count_entry->use; + int32_t new_use_count = use_count_entry->count; + + if (use && (!strcmp(use, FOO_USE_BARRING) || !strcmp(use, FOO_USE_RELEASING)) + && new_use_count > 1) { + LOGPFSMLSRC(foo->fi, LOGL_ERROR, file, line, + "Attempt to get more than one %s\n", use); + /* Fix the use count */ + use_count_entry->count = 1; + return -ERANGE; + } + + LOGPFSMLSRC(foo->fi, LOGL_NOTICE, file, line, "%s %+d %s: now used by %s\n", + foo->fi->id, new_use_count - old_use_count, use ? : "NULL", use_count_name(use_count)); + + if (new_use_count < 0) { + LOGPFSMLSRC(foo->fi, LOGL_ERROR, file, line, "Negative use count on %s: %s\n", + use ? : "NULL", use_count_name(use_count)); + /* Let it pass for the sake of this test */ + } + + if (osmo_use_count_total(use_count) == 0) + osmo_fsm_inst_dispatch(foo->fi, FOO_EV_UNUSED, NULL); + return 0; +} + +#define foo_get_put(FOO, USE, CHANGE) do { \ + int rc = osmo_use_count_get_put(&(FOO)->use_count, USE, CHANGE); \ + if (rc) \ + log("osmo_use_count_get_put(%s, %s, %d) returned error: %d %s\n", \ + (FOO)->fi->id, USE ? : "NULL", CHANGE, rc, strerror(-rc)); \ + } while(0) + +#define foo_get(FOO, USE) foo_get_put(FOO, USE, 1) +#define foo_put(FOO, USE) foo_get_put(FOO, USE, -1) + +enum foo_fsm_states { + FOO_ST_IN_USE, + FOO_ST_IN_RELEASE, +}; + +void foo_fsm_in_use(struct osmo_fsm_inst *fi, uint32_t event, void *data) +{ + OSMO_ASSERT(event == FOO_EV_UNUSED); + osmo_fsm_inst_state_chg(fi, FOO_ST_IN_RELEASE, 0, 0); +} + +void foo_fsm_in_release_onenter(struct osmo_fsm_inst *fi, uint32_t prev_state) +{ + struct foo *foo = fi->priv; + foo_get(foo, FOO_USE_RELEASING); +} + +void foo_fsm_in_release(struct osmo_fsm_inst *fi, uint32_t event, void *data) +{ + OSMO_ASSERT(event == FOO_EV_UNUSED); + osmo_fsm_inst_term(fi, OSMO_FSM_TERM_REGULAR, NULL); +} + + +#define S(x) (1 << (x)) + +static const struct osmo_fsm_state foo_fsm_states[] = { + [FOO_ST_IN_USE] = { + .name = "IN_USE", + .in_event_mask = 0 + | S(FOO_EV_UNUSED) + , + .out_state_mask = 0 + | S(FOO_ST_IN_RELEASE) + , + .action = foo_fsm_in_use, + }, + [FOO_ST_IN_RELEASE] = { + .name = "IN_RELEASE", + .in_event_mask = 0 + | S(FOO_EV_UNUSED) + , + .out_state_mask = 0 + , + .onenter = foo_fsm_in_release_onenter, + .action = foo_fsm_in_release, + }, +}; + +static const struct value_string foo_fsm_event_names[] = { + OSMO_VALUE_STRING(FOO_EV_UNUSED), + {} +}; + +void foo_cleanup(struct osmo_fsm_inst *fi, enum osmo_fsm_term_cause cause) +{ + struct foo *foo = fi->priv; + llist_del(&foo->entry); +} + +static struct osmo_fsm foo_fsm = { + .name = "foo", + .states = foo_fsm_states, + .event_names = foo_fsm_event_names, + .num_states = ARRAY_SIZE(foo_fsm_states), + .log_subsys = DFOO, + .cleanup = foo_cleanup, +}; + +static struct foo *foo_alloc(const char *name, size_t static_entries) +{ + struct foo *foo; + struct osmo_fsm_inst *fi = osmo_fsm_inst_alloc(&foo_fsm, ctx, NULL, LOGL_DEBUG, name); + OSMO_ASSERT(fi); + OSMO_ASSERT(static_entries <= ARRAY_SIZE(foo->use_count_buf)); + + foo = talloc_zero(fi, struct foo); + *foo = (struct foo){ + .fi = fi, + .use_count = { + .talloc_object = foo, + .use_cb = foo_use_cb, + }, + }; + fi->priv = foo; + + osmo_use_count_make_static_entries(&foo->use_count, foo->use_count_buf, static_entries); + + llist_add_tail(&foo->entry, &all_foo); + return foo; +} + +void print_foos() +{ + int count = 0; + struct foo *foo; + fprintf(stderr, "\nall use counts:\n"); + llist_for_each_entry(foo, &all_foo, entry) { + fprintf(stderr, "%s: %s\n", foo->fi->id, use_count_name(&foo->use_count)); + count++; + } + fprintf(stderr, "%d foos\n\n", count); +} + +static void test_use_count_fsm() +{ + struct foo *a, *b, *c; + log("\n%s()\n", __func__); + + a = foo_alloc("a", 0); + b = foo_alloc("b", 2); + c = foo_alloc("c", 10); + print_foos(); + + log("A few gets and puts, logging source file information\n"); + log_set_print_filename2(osmo_stderr_target, LOG_FILENAME_BASENAME); + foo_get(a, FOO_USE_BARRING); + + foo_get(b, FOO_USE_BARRING); + foo_get(b, FOO_USE_FIGHTING); + + print_foos(); + + log("Attempt to get more than one on limited 'barring' user:\n"); + foo_get(b, FOO_USE_BARRING); + print_foos(); + + log("Put away one user of b\n"); + foo_put(b, FOO_USE_BARRING); + print_foos(); + + log("(no longer log source file information)\n"); + log_set_print_filename2(osmo_stderr_target, LOG_FILENAME_NONE); + + log("Test null use token\n"); + foo_get(a, NULL); + print_foos(); + foo_put(a, NULL); + print_foos(); + + log("Put away last user of a, goes to RELEASING state and waits for a hypothetic async release process\n"); + foo_put(a, FOO_USE_BARRING); + print_foos(); + + log("Async releasing of a is done, will dealloc\n"); + foo_put(a, FOO_USE_RELEASING); + print_foos(); + + log("Use b multiple times\n"); + foo_get(b, FOO_USE_KUNG); + foo_get(b, FOO_USE_KUNG); + + foo_put(b, FOO_USE_KUNG); + foo_get(b, FOO_USE_KUNG); + + foo_get(b, FOO_USE_KUNG); + print_foos(); + + log("Test range: set kung-fu to INT32_MAX-1, then get three more; total count gets max-clamped to INT32_MAX\n"); + foo_get_put(b, FOO_USE_KUNG, INT32_MAX-1 - osmo_use_count_by(&b->use_count, FOO_USE_KUNG)); + print_foos(); + foo_get(b, FOO_USE_KUNG); + foo_get(b, FOO_USE_KUNG); + foo_get(b, FOO_USE_KUNG); + foo_get_put(b, FOO_USE_FIGHTING, 2); + foo_get_put(b, FOO_USE_KUNG, -3); + foo_put(b, FOO_USE_KUNG); + foo_put(b, FOO_USE_KUNG); + foo_get(b, FOO_USE_FIGHTING); + foo_get(b, FOO_USE_FIGHTING); + foo_get(b, FOO_USE_FIGHTING); + print_foos(); + + log("Release all uses of b\n"); + foo_get_put(b, FOO_USE_KUNG, - osmo_use_count_by(&b->use_count, FOO_USE_KUNG)); + foo_get_put(b, FOO_USE_FIGHTING, - osmo_use_count_by(&b->use_count, FOO_USE_FIGHTING)); + + log("Signal async release as done\n"); + foo_put(b, FOO_USE_RELEASING); + print_foos(); + + log("Release something not gotten before: a get/put bug goes into negative count\n"); + foo_put(c, FOO_USE_KUNG); + print_foos(); + log("More negative\n"); + foo_put(c, FOO_USE_KUNG); + foo_put(c, FOO_USE_KUNG); + print_foos(); + + log("Also release c\n"); + foo_get_put(c, FOO_USE_KUNG, 4); + foo_put(c, FOO_USE_KUNG); + log("Signal async release as done\n"); + foo_put(c, FOO_USE_RELEASING); + print_foos(); +} + +static const struct log_info_cat default_categories[] = { + [DFOO] = { + .name = "DFOO", + .description = "FOO", + .enabled = 1, .loglevel = LOGL_DEBUG, + }, +}; + +static const struct log_info log_info = { + .cat = default_categories, + .num_cat = ARRAY_SIZE(default_categories), +}; + + +int main(int argc, char **argv) +{ + ctx = talloc_named_const(NULL, 0, "use_count_test.c"); + + osmo_fsm_log_addr(false); + + osmo_init_logging2(ctx, &log_info); + + log_set_print_filename2(osmo_stderr_target, LOG_FILENAME_BASENAME); + log_set_print_filename2(osmo_stderr_target, LOG_FILENAME_NONE); + log_set_print_filename_pos(osmo_stderr_target, LOG_FILENAME_POS_LINE_END); + log_set_print_category(osmo_stderr_target, 1); + log_set_print_category_hex(osmo_stderr_target, 0); + log_set_print_level(osmo_stderr_target, 1); + log_set_use_color(osmo_stderr_target, 0); + + osmo_fsm_register(&foo_fsm); + + test_use_count_fsm(); + + return EXIT_SUCCESS; +} diff --git a/tests/use_count/use_count_test.err b/tests/use_count/use_count_test.err new file mode 100644 index 00000000..97e74a51 --- /dev/null +++ b/tests/use_count/use_count_test.err @@ -0,0 +1,171 @@ + +test_use_count_fsm() +DFOO DEBUG foo(a){IN_USE}: Allocated +DFOO DEBUG foo(b){IN_USE}: Allocated +DFOO DEBUG foo(c){IN_USE}: Allocated + +all use counts: +a: 0 (-) +b: 0 (-) +c: 0 (-) +3 foos + +A few gets and puts, logging source file information +DFOO NOTICE foo(a){IN_USE}: a +1 barring: now used by 1 (barring) (use_count_test.c:223) +DFOO NOTICE foo(b){IN_USE}: b +1 barring: now used by 1 (barring) (use_count_test.c:225) +DFOO NOTICE foo(b){IN_USE}: b +1 fighting: now used by 2 (barring,fighting) (use_count_test.c:226) + +all use counts: +a: 1 (barring) +b: 2 (barring,fighting) +c: 0 (-) +3 foos + +Attempt to get more than one on limited 'barring' user: +DFOO ERROR foo(b){IN_USE}: Attempt to get more than one barring (use_count_test.c:231) +osmo_use_count_get_put(b, barring, 1) returned error: -34 Numerical result out of range + +all use counts: +a: 1 (barring) +b: 2 (barring,fighting) +c: 0 (-) +3 foos + +Put away one user of b +DFOO NOTICE foo(b){IN_USE}: b -1 barring: now used by 1 (fighting) (use_count_test.c:235) + +all use counts: +a: 1 (barring) +b: 1 (fighting) +c: 0 (-) +3 foos + +(no longer log source file information) +Test null use token +DFOO NOTICE foo(a){IN_USE}: a +1 NULL: now used by 2 (barring,NULL) + +all use counts: +a: 2 (barring,NULL) +b: 1 (fighting) +c: 0 (-) +3 foos + +DFOO NOTICE foo(a){IN_USE}: a -1 NULL: now used by 1 (barring) + +all use counts: +a: 1 (barring) +b: 1 (fighting) +c: 0 (-) +3 foos + +Put away last user of a, goes to RELEASING state and waits for a hypothetic async release process +DFOO NOTICE foo(a){IN_USE}: a -1 barring: now used by 0 (-) +DFOO DEBUG foo(a){IN_USE}: Received Event FOO_EV_UNUSED +DFOO DEBUG foo(a){IN_USE}: state_chg to IN_RELEASE +DFOO NOTICE foo(a){IN_RELEASE}: a +1 releasing: now used by 1 (releasing) + +all use counts: +a: 1 (releasing) +b: 1 (fighting) +c: 0 (-) +3 foos + +Async releasing of a is done, will dealloc +DFOO NOTICE foo(a){IN_RELEASE}: a -1 releasing: now used by 0 (-) +DFOO DEBUG foo(a){IN_RELEASE}: Received Event FOO_EV_UNUSED +DFOO DEBUG foo(a){IN_RELEASE}: Terminating (cause = OSMO_FSM_TERM_REGULAR) +DFOO DEBUG foo(a){IN_RELEASE}: Freeing instance +DFOO DEBUG foo(a){IN_RELEASE}: Deallocated + +all use counts: +b: 1 (fighting) +c: 0 (-) +2 foos + +Use b multiple times +DFOO NOTICE foo(b){IN_USE}: b +1 kungfoo: now used by 2 (fighting,kungfoo) +DFOO NOTICE foo(b){IN_USE}: b +1 kungfoo: now used by 3 (fighting,2*kungfoo) +DFOO NOTICE foo(b){IN_USE}: b -1 kungfoo: now used by 2 (fighting,kungfoo) +DFOO NOTICE foo(b){IN_USE}: b +1 kungfoo: now used by 3 (fighting,2*kungfoo) +DFOO NOTICE foo(b){IN_USE}: b +1 kungfoo: now used by 4 (fighting,3*kungfoo) + +all use counts: +b: 4 (fighting,3*kungfoo) +c: 0 (-) +2 foos + +Test range: set kung-fu to INT32_MAX-1, then get three more; total count gets max-clamped to INT32_MAX +DFOO NOTICE foo(b){IN_USE}: b +2147483643 kungfoo: now used by 2147483647 (fighting,2147483646*kungfoo) + +all use counts: +b: 2147483647 (fighting,2147483646*kungfoo) +c: 0 (-) +2 foos + +DFOO NOTICE foo(b){IN_USE}: b +1 kungfoo: now used by 2147483647 (fighting,2147483647*kungfoo) +osmo_use_count_get_put(b, kungfoo, 1) returned error: -34 Numerical result out of range +osmo_use_count_get_put(b, kungfoo, 1) returned error: -34 Numerical result out of range +DFOO NOTICE foo(b){IN_USE}: b +2 fighting: now used by 2147483647 (3*fighting,2147483647*kungfoo) +DFOO NOTICE foo(b){IN_USE}: b -3 kungfoo: now used by 2147483647 (3*fighting,2147483644*kungfoo) +DFOO NOTICE foo(b){IN_USE}: b -1 kungfoo: now used by 2147483646 (3*fighting,2147483643*kungfoo) +DFOO NOTICE foo(b){IN_USE}: b -1 kungfoo: now used by 2147483645 (3*fighting,2147483642*kungfoo) +DFOO NOTICE foo(b){IN_USE}: b +1 fighting: now used by 2147483646 (4*fighting,2147483642*kungfoo) +DFOO NOTICE foo(b){IN_USE}: b +1 fighting: now used by 2147483647 (5*fighting,2147483642*kungfoo) +DFOO NOTICE foo(b){IN_USE}: b +1 fighting: now used by 2147483647 (6*fighting,2147483642*kungfoo) + +all use counts: +b: 2147483647 (6*fighting,2147483642*kungfoo) +c: 0 (-) +2 foos + +Release all uses of b +DFOO NOTICE foo(b){IN_USE}: b -2147483642 kungfoo: now used by 6 (6*fighting) +DFOO NOTICE foo(b){IN_USE}: b -6 fighting: now used by 0 (-) +DFOO DEBUG foo(b){IN_USE}: Received Event FOO_EV_UNUSED +DFOO DEBUG foo(b){IN_USE}: state_chg to IN_RELEASE +DFOO NOTICE foo(b){IN_RELEASE}: b +1 releasing: now used by 1 (releasing) +Signal async release as done +DFOO NOTICE foo(b){IN_RELEASE}: b -1 releasing: now used by 0 (-) +DFOO DEBUG foo(b){IN_RELEASE}: Received Event FOO_EV_UNUSED +DFOO DEBUG foo(b){IN_RELEASE}: Terminating (cause = OSMO_FSM_TERM_REGULAR) +DFOO DEBUG foo(b){IN_RELEASE}: Freeing instance +DFOO DEBUG foo(b){IN_RELEASE}: Deallocated + +all use counts: +c: 0 (-) +1 foos + +Release something not gotten before: a get/put bug goes into negative count +DFOO NOTICE foo(c){IN_USE}: c -1 kungfoo: now used by -1 (-1*kungfoo) +DFOO ERROR foo(c){IN_USE}: Negative use count on kungfoo: -1 (-1*kungfoo) + +all use counts: +c: -1 (-1*kungfoo) +1 foos + +More negative +DFOO NOTICE foo(c){IN_USE}: c -1 kungfoo: now used by -2 (-2*kungfoo) +DFOO ERROR foo(c){IN_USE}: Negative use count on kungfoo: -2 (-2*kungfoo) +DFOO NOTICE foo(c){IN_USE}: c -1 kungfoo: now used by -3 (-3*kungfoo) +DFOO ERROR foo(c){IN_USE}: Negative use count on kungfoo: -3 (-3*kungfoo) + +all use counts: +c: -3 (-3*kungfoo) +1 foos + +Also release c +DFOO NOTICE foo(c){IN_USE}: c +4 kungfoo: now used by 1 (kungfoo) +DFOO NOTICE foo(c){IN_USE}: c -1 kungfoo: now used by 0 (-) +DFOO DEBUG foo(c){IN_USE}: Received Event FOO_EV_UNUSED +DFOO DEBUG foo(c){IN_USE}: state_chg to IN_RELEASE +DFOO NOTICE foo(c){IN_RELEASE}: c +1 releasing: now used by 1 (releasing) +Signal async release as done +DFOO NOTICE foo(c){IN_RELEASE}: c -1 releasing: now used by 0 (-) +DFOO DEBUG foo(c){IN_RELEASE}: Received Event FOO_EV_UNUSED +DFOO DEBUG foo(c){IN_RELEASE}: Terminating (cause = OSMO_FSM_TERM_REGULAR) +DFOO DEBUG foo(c){IN_RELEASE}: Freeing instance +DFOO DEBUG foo(c){IN_RELEASE}: Deallocated + +all use counts: +0 foos + diff --git a/tests/use_count/use_count_test.ok b/tests/use_count/use_count_test.ok new file mode 100644 index 00000000..e69de29b -- cgit v1.2.3