summaryrefslogtreecommitdiffstats
path: root/tests
diff options
context:
space:
mode:
authorNeels Hofmeyr <neels@hofmeyr.de>2019-02-11 20:32:25 +0100
committerNeels Hofmeyr <nhofmeyr@sysmocom.de>2019-04-08 13:47:17 +0000
commit0e8df1c7e48bcae2285c7c138bd50f932049bd24 (patch)
treeebc61be55958db4925f412bfb55906cf100d94eb /tests
parent0c7826e9bd8026b239d320dba49416fd603f17fd (diff)
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
Diffstat (limited to 'tests')
-rw-r--r--tests/Makefile.am5
-rw-r--r--tests/testsuite.at7
-rw-r--r--tests/use_count/use_count_test.c339
-rw-r--r--tests/use_count/use_count_test.err171
-rw-r--r--tests/use_count/use_count_test.ok0
5 files changed, 522 insertions, 0 deletions
diff --git a/tests/Makefile.am b/tests/Makefile.am
index 88bcd7e9..d123ee2a 100644
--- a/tests/Makefile.am
+++ b/tests/Makefile.am
@@ -31,6 +31,7 @@ check_PROGRAMS = timer/timer_test sms/sms_test ussd/ussd_test \
tdef/tdef_vty_test_config_subnode \
tdef/tdef_vty_test_dynamic \
sockaddr_str/sockaddr_str_test \
+ use_count/use_count_test \
$(NULL)
if ENABLE_MSGFILE
@@ -240,6 +241,9 @@ tdef_tdef_vty_test_dynamic_LDADD = $(LDADD) $(top_builddir)/src/vty/libosmovty.l
sockaddr_str_sockaddr_str_test_SOURCES = sockaddr_str/sockaddr_str_test.c
sockaddr_str_sockaddr_str_test_LDADD = $(LDADD)
+use_count_use_count_test_SOURCES = use_count/use_count_test.c
+use_count_use_count_test_LDADD = $(LDADD)
+
# The `:;' works around a Bash 3.2 bug when the output is not writeable.
$(srcdir)/package.m4: $(top_srcdir)/configure.ac
:;{ \
@@ -309,6 +313,7 @@ EXTRA_DIST = testsuite.at $(srcdir)/package.m4 $(TESTSUITE) \
tdef/tdef_vty_test_config_subnode.vty \
tdef/tdef_vty_test_dynamic.vty \
sockaddr_str/sockaddr_str_test.ok \
+ use_count/use_count_test.ok use_count/use_count_test.err \
$(NULL)
DISTCLEANFILES = atconfig atlocal conv/gsm0503_test_vectors.c
diff --git a/tests/testsuite.at b/tests/testsuite.at
index db2003f4..5a6e8020 100644
--- a/tests/testsuite.at
+++ b/tests/testsuite.at
@@ -337,3 +337,10 @@ AT_KEYWORDS([sockaddr_str])
cat $abs_srcdir/sockaddr_str/sockaddr_str_test.ok > expout
AT_CHECK([$abs_top_builddir/tests/sockaddr_str/sockaddr_str_test], [0], [expout], [ignore])
AT_CLEANUP
+
+AT_SETUP([use_count])
+AT_KEYWORDS([use_count])
+cat $abs_srcdir/use_count/use_count_test.ok > expout
+cat $abs_srcdir/use_count/use_count_test.err > experr
+AT_CHECK([$abs_top_builddir/tests/use_count/use_count_test], [0], [expout], [experr])
+AT_CLEANUP
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