From 911e6e6ed3502c7135cd400f7e8872a5412d362b Mon Sep 17 00:00:00 2001 From: Olof hagsand Date: Thu, 1 Nov 2018 21:34:27 +0100 Subject: [PATCH] stream debugging --- apps/backend/backend_client.c | 9 ++-- apps/backend/backend_main.c | 2 +- apps/backend/clixon_backend_handle.c | 12 +++-- lib/src/clixon_stream.c | 19 +++++--- test/all.sh | 2 + test/test_stream.sh | 68 ++++++++++++++++++++-------- util/clixon_util_stream.c | 3 +- 7 files changed, 83 insertions(+), 32 deletions(-) diff --git a/apps/backend/backend_client.c b/apps/backend/backend_client.c index 4f69de8d..fedad77a 100644 --- a/apps/backend/backend_client.c +++ b/apps/backend/backend_client.c @@ -88,7 +88,7 @@ ce_find_bypid(struct client_entry *ce_list, * @param[in] arg Extra argument provided in stream_ss_add * @see stream_ss_add */ -static int +int ce_event_cb(clicon_handle h, int op, cxobj *event, @@ -111,6 +111,7 @@ ce_event_cb(clicon_handle h, break; } } + clicon_debug(1, "%s retval:0", __FUNCTION__); return 0; } @@ -130,6 +131,8 @@ backend_client_rm(clicon_handle h, struct client_entry **ce_prev; clicon_debug(1, "%s", __FUNCTION__); + /* for all streams: XXX better to do it top-level? */ + stream_ss_delete_all(h, ce_event_cb, (void*)ce); c0 = backend_client_list(h); ce_prev = &c0; /* this points to stack and is not real backpointer */ for (c = *ce_prev; c; c = c->ce_next){ @@ -139,12 +142,11 @@ backend_client_rm(clicon_handle h, close(ce->ce_s); ce->ce_s = 0; } - /* for all streams */ - stream_ss_delete_all(h, ce_event_cb, (void*)ce); break; } ce_prev = &c->ce_next; } + return backend_client_delete(h, ce); /* actually purge it */ } @@ -878,6 +880,7 @@ from_client_create_subscription(clicon_handle h, goto done; goto ok; } + /* Add subscriber to stream - to make notifications for this client */ if (stream_ss_add(h, stream, selector, starttime?&start:NULL, stoptime?&stop:NULL, ce_event_cb, (void*)ce) < 0) diff --git a/apps/backend/backend_main.c b/apps/backend/backend_main.c index 780381a4..3856eb0e 100644 --- a/apps/backend/backend_main.c +++ b/apps/backend/backend_main.c @@ -102,7 +102,7 @@ backend_terminate(clicon_handle h) if (sockpath) unlink(sockpath); xmldb_plugin_unload(h); /* unload storage plugin */ - backend_handle_exit(h); /* Cannot use h after this */ + backend_handle_exit(h); /* Also deletes streams. Cannot use h after this. */ event_exit(); clicon_debug(1, "%s done", __FUNCTION__); clicon_log_exit(); diff --git a/apps/backend/clixon_backend_handle.c b/apps/backend/clixon_backend_handle.c index 4876fcbb..8ed13d97 100644 --- a/apps/backend/clixon_backend_handle.c +++ b/apps/backend/clixon_backend_handle.c @@ -104,6 +104,7 @@ backend_handle_init(void) /*! Deallocates a backend handle, including all client structs * @Note: handle 'h' cannot be used in calls after this + * @see backend_client_rm */ int backend_handle_exit(clicon_handle h) @@ -111,12 +112,17 @@ backend_handle_exit(clicon_handle h) struct backend_handle *bh = handle(h); struct client_entry *ce; - /* only delete client structs, not close sockets, etc, see backend_client_rm */ - while ((ce = backend_client_list(h)) != NULL) + /* only delete client structs, not close sockets, etc, see backend_client_rm WHY NOT? */ + while ((ce = backend_client_list(h)) != NULL){ + if (ce->ce_s){ + close(ce->ce_s); + ce->ce_s = 0; + } backend_client_delete(h, ce); + } if (bh->bh_nacm) xml_free(bh->bh_nacm); - clicon_handle_exit(h); /* frees h and options */ + clicon_handle_exit(h); /* frees h and options (and streams) */ return 0; } diff --git a/lib/src/clixon_stream.c b/lib/src/clixon_stream.c index 2b0316b5..1659956e 100644 --- a/lib/src/clixon_stream.c +++ b/lib/src/clixon_stream.c @@ -38,9 +38,14 @@ * 3) Stream replay: stream_replay/_add * 4) nginx/nchan publish code (use --enable-publish config option) * - * +---------------+ * +---------------+ * +---------------+ - * | clicon_handle |--------->| event_stream |--------->| subscription | - * +---------------+ +---------------+ +---------------+ + * + * +---------------+ 1 arg + * | client_entry | <----------------- +---------------+ + * +---------------+ +-->| subscription | + * / +---------------+ + * +---------------+ * +---------------+ + * | clicon_handle |--------->| event_stream | + * +---------------+ +---------------+ * \ * +---------------+ * +-->| replay | * +---------------+ @@ -164,7 +169,7 @@ stream_delete_all(clicon_handle h) if (es->es_description) free(es->es_description); while ((ss = es->es_subscription) != NULL) - stream_ss_rm(h, es, ss); + stream_ss_rm(h, es, ss); /* XXX in some cases leaks memory due to DONT clause in stream_ss_rm() */ while ((r = es->es_replay) != NULL){ DELQ(r, es->es_replay, struct stream_replay *); if (r->r_xml) @@ -379,12 +384,14 @@ stream_ss_rm(clicon_handle h, DELQ(ss, es->es_subscription, struct stream_subscription *); /* Remove from upper layers - close socket etc. */ (*ss->ss_fn)(h, 1, NULL, ss->ss_arg); +#ifdef DONT /* upcall may have deleted it */ if (ss->ss_stream) free(ss->ss_stream); if (ss->ss_xpath) free(ss->ss_xpath); free(ss); - +#endif + clicon_debug(1, "%s retval: 0", __FUNCTION__); return 0; } @@ -480,7 +487,7 @@ stream_notify_xml(clicon_handle h, goto done; ss = NEXTQ(struct stream_subscription *, ss); } - } while (ss && ss != es->es_subscription); + } while (es->es_subscription && ss != es->es_subscription); retval = 0; done: return retval; diff --git a/test/all.sh b/test/all.sh index 233438ea..d0e92410 100755 --- a/test/all.sh +++ b/test/all.sh @@ -1,4 +1,6 @@ #!/bin/bash +# Run, eg as: +# ./run.sh 2>&1 | tee test.log # include err() and new() functions . ./lib.sh diff --git a/test/test_stream.sh b/test/test_stream.sh index 4a40d5bb..b00d53fd 100755 --- a/test/test_stream.sh +++ b/test/test_stream.sh @@ -13,11 +13,12 @@ # - stream retention time # - native vs nchan implementation # Focussing on 1-3 -# 2a) start sub 8s - see 2 notifications -# 2b) start sub 8s - stoptime after 5s - see 1 notifications -# 2c) start sub 8s - replay from start -8s - see 4 notifications -# 2d) start sub 8s - replay from start -8s to stop +4s - see 3 notifications -# 2e) start sub 8s - replay from -90s w retention 60s - see 10 notifications +# 2a) start sub 8s - expect 2 notifications +# 2b) start sub 8s - stoptime after 5s - expect 1 notifications +# 2c) start sub 8s - replay from start -8s - expect 4 notifications +# 2d) start sub 8s - replay from start -8s to stop +4s - expect 3 notifications +# 2e) start sub 8s - replay from -90s w retention 60s - expect 10 notifications +# Note the sleeps are mainly for valgrind usage APPNAME=example UTIL=../util/clixon_util_stream @@ -127,7 +128,7 @@ expecteof "$clixon_netconf -qf $cfg -y $fyang" 0 'EXAMPLE]]>]]>' '^]]>]]>20' 5 +expectwait "$clixon_netconf -qf $cfg -y $fyang" 'EXAMPLE]]>]]>' '^]]>]]>20' 10 new "netconf subscription with empty startTime" expectwait "$clixon_netconf -qf $cfg -y $fyang" 'EXAMPLE]]>]]>' '^]]>]]>20' 5 @@ -148,7 +149,7 @@ expectwait "$clixon_netconf -qf $cfg -y $fyang" 'EXAMPLE$NOW]]>]]>" '^]]>]]>20' 10 - +sleep 2 # # 2. Restconf RFC8040 stream testing new "2. Restconf RFC8040 stream testing" @@ -156,16 +157,19 @@ new "2. Restconf RFC8040 stream testing" new "restconf event stream discovery RFC8040 Sec 6.2" expectfn "curl -s -X GET http://localhost/restconf/data/ietf-restconf-monitoring:restconf-state/streams" 0 '{"streams": {"stream": \[{"name": "EXAMPLE","description": "Example event stream","replay-support": true,"access": \[{"encoding": "xml","location": "https://localhost/streams/EXAMPLE"}\]}\]}' +sleep 2 new "restconf subscribe RFC8040 Sec 6.3, get location" expectfn "curl -s -X GET http://localhost/restconf/data/ietf-restconf-monitoring:restconf-state/streams/stream=EXAMPLE/access=xml/location" 0 '{"location": "https://localhost/streams/EXAMPLE"}' +sleep 2 # Restconf stream subscription RFC8040 Sec 6.3 # Start Subscription w error new "restconf monitor event nonexist stream" expectwait 'curl -s -X GET -H "Accept: text/event-stream" -H "Cache-Control: no-cache" -H "Connection: keep-alive" http://localhost/streams/NOTEXIST' 0 'invalid-valueapplicationerrorNo such stream' 2 -# 2a) start subscription 8s - see 1-2 notifications -new "2a) start subscriptions 8s - see 2 notifications" + +# 2a) start subscription 8s - expect 1-2 notifications +new "2a) start subscriptions 8s - expect 1-2 notifications" ret=$($UTIL -u http://localhost/streams/EXAMPLE -t 8) expect="data: ${DATE}T[0-9:.]*faultEthernet0major" @@ -174,13 +178,13 @@ if [ -z "$match" ]; then err "$expect" "$ret" fi nr=$(echo "$ret" | grep -c "data:") -if [ $nr != 1 -a $nr != 2 ]; then +if [ $nr -lt 1 -o $nr -gt 2 ]; then err 2 "$nr" fi sleep 2 -# 2b) start subscription 8s - stoptime after 5s - see 1-2 notifications -new "2b) start subscriptions 8s - stoptime after 5s - see 1 notifications" +# 2b) start subscription 8s - stoptime after 5s - expect 1-2 notifications +new "2b) start subscriptions 8s - stoptime after 5s - expect 1-2 notifications" ret=$($UTIL -u http://localhost/streams/EXAMPLE -t 8 -e +10) expect="data: ${DATE}T[0-9:.]*faultEthernet0major" match=$(echo "$ret" | grep -Eo "$expect") @@ -188,13 +192,12 @@ if [ -z "$match" ]; then err "$expect" "$ret" fi nr=$(echo "$ret" | grep -c "data:") -if [ $nr != 1 -a $nr != 2 ]; then +if [ $nr -lt 1 -o $nr -gt 2 ]; then err 1 "$nr" fi -sleep 2 # 2c -new "2c) start sub 8s - replay from start -8s - see 3-4 notifications" +new "2c) start sub 8s - replay from start -8s - expect 3-4 notifications" ret=$($UTIL -u http://localhost/streams/EXAMPLE -t 10 -s -8) expect="data: ${DATE}T[0-9:.]*faultEthernet0major" match=$(echo "$ret" | grep -Eo "$expect") @@ -202,10 +205,37 @@ if [ -z "$match" ]; then err "$expect" "$ret" fi nr=$(echo "$ret" | grep -c "data:") -if [ $nr != 3 -a $nr != 4 ]; then +if [ $nr -lt 3 -o $nr -gt 4 ]; then err 4 "$nr" fi -exit + +# 2d) start sub 8s - replay from start -8s to stop +4s - expect 3 notifications +new "2d) start sub 8s - replay from start -8s to stop +4s - expect 3 notifications" +ret=$($UTIL -u http://localhost/streams/EXAMPLE -t 10 -s -30 -e +4) +expect="data: ${DATE}T[0-9:.]*faultEthernet0major" +match=$(echo "$ret" | grep -Eo "$expect") +if [ -z "$match" ]; then + err "$expect" "$ret" +fi +nr=$(echo "$ret" | grep -c "data:") +if [ $nr -lt 4 -o $nr -gt 10 ]; then + err 6 "$nr" +fi + +# 2e) start sub 8s - replay from -90s w retention 60s - expect 10 notifications +new "2e) start sub 8s - replay from -90s w retention 60s - expect 10 notifications" +ret=$($UTIL -u http://localhost/streams/EXAMPLE -t 10 -s -90 -e +0) +expect="data: ${DATE}T[0-9:.]*faultEthernet0major" +match=$(echo "$ret" | grep -Eo "$expect") +if [ -z "$match" ]; then + err "$expect" "$ret" +fi +nr=$(echo "$ret" | grep -c "data:") + +if [ $nr -lt 10 -o $nr -gt 14 ]; then + err 10 "$nr" +fi + #----------------- sudo pkill -u www-data clixon_restconf @@ -224,7 +254,9 @@ if [ -n "$pid" ]; then fi rm -rf $dir -exit + +exit # DONT REMOVE MANUAL TESTING + #-------------------------------------------------------------------- # Need manual testing new "restconf monitor streams native NEEDS manual testing" diff --git a/util/clixon_util_stream.c b/util/clixon_util_stream.c index 6c802799..15c3cef3 100644 --- a/util/clixon_util_stream.c +++ b/util/clixon_util_stream.c @@ -118,7 +118,8 @@ stream_url_get(char *url, struct curl_slist *list = NULL; int ret; - clicon_debug(1, "%s: curl -G %s", __FUNCTION__, url); + clicon_debug(1, "%s: curl -G %s start-time=%s stop-time=%s", + __FUNCTION__, url, start?start:"", stop?stop:""); /* Set up curl for doing the communication with the controller */ if ((curl = curl_easy_init()) == NULL) { clicon_err(OE_PLUGIN, errno, "curl_easy_init");