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

3 files changed, 510 insertions, 0 deletions

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 <info@sysmocom.de>
+ *
+ * All Rights Reserved
+ *
+ * Author: Neels Hofmeyr <neels@hofmeyr.de>
+ *
+ * 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 <stdio.h>
+#include <errno.h>
+#include <string.h>
+#include <limits.h>
+
+#include <osmocom/core/logging.h>
+#include <osmocom/core/application.h>
+#include <osmocom/core/fsm.h>
+
+#include <osmocom/core/use_count.h>
+
+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
--- /dev/null
+++ b/tests/use_count/use_count_test.ok