From e0ba90207be05cf28ee04c579c8d77503c31cca7 Mon Sep 17 00:00:00 2001 From: Olof hagsand Date: Thu, 22 Sep 2022 14:22:38 +0200 Subject: [PATCH] Restconf callhome idle timer fix Leak in restconf http/1 data path: when multiple packets in same connection. --- apps/restconf/restconf_http1.c | 7 +- apps/restconf/restconf_native.c | 73 ++++---- apps/restconf/restconf_native.h | 2 +- test/test_restconf_callhome.sh | 39 +++-- test/test_restconf_op.sh | 25 ++- util/clixon_restconf_callhome_client.c | 226 ++++++++++++++++--------- 6 files changed, 254 insertions(+), 118 deletions(-) diff --git a/apps/restconf/restconf_http1.c b/apps/restconf/restconf_http1.c index 3cd1ec8f..db8cdf05 100644 --- a/apps/restconf/restconf_http1.c +++ b/apps/restconf/restconf_http1.c @@ -301,6 +301,7 @@ restconf_http1_reply(restconf_conn *rc, int retval = -1; cg_var *cv; + clicon_debug(1, "%s", __FUNCTION__); /* If body, add a content-length header * A server MUST NOT send a Content-Length header field in any response * with a status code of 1xx (Informational) or 204 (No Content). A @@ -333,6 +334,8 @@ restconf_http1_reply(restconf_conn *rc, clicon_err(OE_RESTCONF, errno, "cbuf_append_buf"); goto done; } + cbuf_free(sd->sd_body); + sd->sd_body = NULL; } retval = 0; done: @@ -387,8 +390,10 @@ restconf_http1_path_root(clicon_handle h, /* XXX gives mem leak in multiple requests, * but maybe the error is that sd is not freed. */ - if (sd->sd_path != NULL) + if (sd->sd_path != NULL){ free(sd->sd_path); + sd->sd_path = NULL; + } #endif if ((sd->sd_path = restconf_uripath(rc->rc_h)) == NULL) goto done; // XXX SHOULDNT EXIT if no REQUEST_URI diff --git a/apps/restconf/restconf_native.c b/apps/restconf/restconf_native.c index 77b7b655..79f79a69 100644 --- a/apps/restconf/restconf_native.c +++ b/apps/restconf/restconf_native.c @@ -288,8 +288,8 @@ ssl_x509_name_oneline(SSL *ssl, * @param[in] rc Restconf connection handle * @param[in] sd Http stream * @param[out] term Terminate session - * @retval -1 Error * @retval 0 OK + * @retval -1 Error * @see restconf_accept_client where connection can be exited at an earlier stage */ int @@ -365,6 +365,11 @@ restconf_connection_sanity(clicon_handle h, /* Write buf to socket * see also this function in restcont_api_openssl.c + * @param[in] h Clixon handle + * @param[in] buf Buffer to write + * @param[in] buflen Length of buffer + * @param[in] rc Connection struct + * @param[in] callfn For debug * @retval 1 OK * @retval 0 OK, but socket write returned error, caller should close rc * @retval -1 Error @@ -373,7 +378,8 @@ static int native_buf_write(clicon_handle h, char *buf, size_t buflen, - restconf_conn *rc) + restconf_conn *rc, + const char *callfn) { int retval = -1; ssize_t len; @@ -400,7 +406,7 @@ native_buf_write(clicon_handle h, } memcpy(dbgstr, buf, sz); dbgstr[sz] = '\0'; - clicon_debug(1, "%s buflen:%zu buf:\n%s", __FUNCTION__, buflen, dbgstr); + clicon_debug(1, "%s %s buflen:%zu buf:\n%s", __FUNCTION__, callfn, buflen, dbgstr); free(dbgstr); } while (totlen < buflen){ @@ -411,8 +417,6 @@ native_buf_write(clicon_handle h, case SSL_ERROR_SYSCALL: /* 5 */ if (er == ECONNRESET || /* Connection reset by peer */ er == EPIPE) { /* Reading end of socket is closed */ - if (0 && restconf_close_ssl_socket(rc, __FUNCTION__, 0) < 0) - goto done; goto closed; /* Close socket and ssl */ } else if (er == EAGAIN){ @@ -444,8 +448,6 @@ native_buf_write(clicon_handle h, // case EBADF: // XXX if this happens there is some larger error case ECONNRESET: /* Connection reset by peer */ case EPIPE: /* Broken pipe */ - if (0 && restconf_close_ssl_socket(rc, __FUNCTION__, 0) < 0) - goto done; goto closed; /* Close socket and ssl */ break; default: @@ -500,7 +502,7 @@ native_send_badrequest(clicon_handle h, cprintf(cb, "\r\n"); if (body) cprintf(cb, "%s\r\n", body); - retval = native_buf_write(h, cbuf_get(cb), cbuf_len(cb), rc); + retval = native_buf_write(h, cbuf_get(cb), cbuf_len(cb), rc, __FUNCTION__); done: if (cb) cbuf_free(cb); @@ -721,7 +723,8 @@ restconf_http1_process(restconf_conn *rc, if ((ret = http1_check_expect(h, rc, sd)) < 0) goto done; if (ret == 1){ - if ((ret = native_buf_write(h, cbuf_get(sd->sd_outp_buf), cbuf_len(sd->sd_outp_buf), rc)) < 0) + if ((ret = native_buf_write(h, cbuf_get(sd->sd_outp_buf), cbuf_len(sd->sd_outp_buf), + rc, __FUNCTION__)) < 0) goto done; cvec_reset(sd->sd_outp_hdrs); cbuf_reset(sd->sd_outp_buf); @@ -755,12 +758,17 @@ restconf_http1_process(restconf_conn *rc, /* main restconf processing */ if (restconf_http1_path_root(h, rc) < 0) goto done; - if ((ret = native_buf_write(h, cbuf_get(sd->sd_outp_buf), cbuf_len(sd->sd_outp_buf), rc)) < 0) + if ((ret = native_buf_write(h, cbuf_get(sd->sd_outp_buf), cbuf_len(sd->sd_outp_buf), + rc, __FUNCTION__)) < 0) goto done; cvec_reset(sd->sd_outp_hdrs); /* Can be done in native_send_reply */ cbuf_reset(sd->sd_outp_buf); cbuf_reset(sd->sd_inbuf); cbuf_reset(sd->sd_indata); + if (sd->sd_qvec){ + cvec_free(sd->sd_qvec); + sd->sd_qvec = NULL; + } if (ret == 0 || rc->rc_exit){ /* Server-initiated exit */ if (restconf_close_ssl_socket(rc, __FUNCTION__, 0) < 0) goto done; @@ -1056,7 +1064,7 @@ restconf_close_ssl_socket(restconf_conn *rc, int sslerr; int er; - clicon_debug(1, "%s", __FUNCTION__); + clicon_debug(1, "%s %s", __FUNCTION__, callfn); if (rc->rc_ssl != NULL){ if (!dontshutdown && (ret = SSL_shutdown(rc->rc_ssl)) < 0){ @@ -1158,15 +1166,17 @@ ssl_alpn_check(clicon_handle h, * @param[in] h Clixon handle * @param[in] s Socket (unix or ip) * @param[in] rsock Socket struct - * @param[out] rcp Restconf connection + * @param[out] rcp Restconf connection, if present and retval=1 + * @retval 1 OK, connection is up, rcp set + * @retval 0 OK, but connection closed + * @retval -1 Error * @see openssl_init_socket where this callback is registered */ int restconf_ssl_accept_client(clicon_handle h, int s, restconf_socket *rsock, - restconf_conn **rcp - ) + restconf_conn **rcp) { int retval = -1; restconf_native_handle *rn = NULL; @@ -1252,7 +1262,7 @@ restconf_ssl_accept_client(clicon_handle h, #endif if (restconf_close_ssl_socket(rc, __FUNCTION__, 1) < 0) goto done; - goto ok; + goto closed; break; case SSL_ERROR_SYSCALL: /* 5 */ /* Some non-recoverable, fatal I/O error occurred. The OpenSSL error queue @@ -1264,7 +1274,7 @@ restconf_ssl_accept_client(clicon_handle h, if (restconf_close_ssl_socket(rc, __FUNCTION__, 1) < 0) goto done; rc = NULL; - goto ok; + goto closed; break; case SSL_ERROR_WANT_READ: /* 2 */ case SSL_ERROR_WANT_WRITE: /* 3 */ @@ -1305,7 +1315,7 @@ restconf_ssl_accept_client(clicon_handle h, if ((ret = ssl_alpn_check(h, alpn, alpnlen, rc, &proto)) < 0) goto done; if (ret == 0) - goto ok; + goto closed; clicon_debug(1, "%s proto:%s", __FUNCTION__, restconf_proto2str(proto)); #if 0 /* Seems too early to fail here, instead let authentication callback deal with this */ @@ -1327,7 +1337,7 @@ restconf_ssl_accept_client(clicon_handle h, goto done; if (restconf_close_ssl_socket(rc, __FUNCTION__, 0) < 0) goto done; - goto ok; + goto closed; } } #endif @@ -1387,13 +1397,15 @@ restconf_ssl_accept_client(clicon_handle h, goto done; if (rcp) *rcp = rc; - ok: - retval = 0; + retval = 1; /* OK, up */ done: clicon_debug(1, "%s retval %d", __FUNCTION__, retval); if (name) free(name); return retval; + closed: + retval = 0; /* OK, closed */ + goto done; } /* restconf_ssl_accept_client */ static int @@ -1458,8 +1470,8 @@ restconf_idle_cb(int fd, clicon_debug(1, "%s \"%s\"", __FUNCTION__, rsock->rs_description); if (rc->rc_callhome && rsock->rs_periodic && rc->rc_s > 0 && rsock->rs_idle_timeout){ gettimeofday(&now, NULL); - timersub(&now, &rc->rc_t, &td); - if (td.tv_sec < rsock->rs_idle_timeout){ + timersub(&now, &rc->rc_t, &td); /* Last packet timestamp */ + if (td.tv_sec >= rsock->rs_idle_timeout){ if (restconf_close_ssl_socket(rc, __FUNCTION__, 0) < 0) goto done; } @@ -1503,7 +1515,7 @@ restconf_idle_timer(restconf_conn *rc) restconf_socket *rsock; if (rc == NULL || !rc->rc_callhome){ - clicon_err(OE_YANG, EINVAL, "rc is NULL or not callhome"); + clicon_err(OE_RESTCONF, EINVAL, "rc is NULL or not callhome"); goto done; } rsock = rc->rc_socket; @@ -1542,6 +1554,7 @@ restconf_callhome_cb(int fd, size_t sa_len; int s; restconf_conn *rc = NULL; + int ret; rsock = (restconf_socket *)arg; if (rsock == NULL || !rsock->rs_callhome){ @@ -1568,11 +1581,13 @@ restconf_callhome_cb(int fd, else { clicon_debug(1, "%s connect %hu OK", __FUNCTION__, rsock->rs_port); rsock->rs_attempts = 0; - if (restconf_ssl_accept_client(h, s, rsock, &rc) < 0) - goto done; - if (rsock->rs_periodic && rsock->rs_idle_timeout && - restconf_idle_timer(rc) < 0) + if ((ret = restconf_ssl_accept_client(h, s, rsock, &rc)) < 0) goto done; + /* ret == 0 means already closed */ + if (ret == 1 && rsock->rs_periodic && rsock->rs_idle_timeout){ + if (restconf_idle_timer(rc) < 0) + goto done; + } } retval = 0; done: @@ -1588,7 +1603,7 @@ restconf_callhome_timer_unreg(restconf_socket *rsock) /*! Set callhome timer, which tries to connect to callhome client * * Implement callhome re-connect strategies in ietf-restconf-server.yang - * NYI: start-with, anchor-time, idle-timeout + * NYI: start-with, anchor-time * @param[in] rsock restconf_socket * @param[in] new if periodic: 1: Force a new period * @see restconf_callhome_timer_unreg @@ -1635,7 +1650,7 @@ restconf_callhome_timer(restconf_socket *rsock, } cprintf(cb, "restconf callhome timer %s", rsock->rs_description); if (rsock->rs_description) - clicon_debug(1, "%s registering \"%s\": %lu", __FUNCTION__, rsock->rs_description, t.tv_sec); + clicon_debug(1, "%s registering \"%s\": +%lu", __FUNCTION__, rsock->rs_description, t.tv_sec-now.tv_sec); else clicon_debug(1, "%s: %lu", __FUNCTION__, t.tv_sec); /* Should be only place restconf_callhome_cb is registered */ diff --git a/apps/restconf/restconf_native.h b/apps/restconf/restconf_native.h index 2867f35e..f6c8c44d 100644 --- a/apps/restconf/restconf_native.h +++ b/apps/restconf/restconf_native.h @@ -147,7 +147,7 @@ typedef struct restconf_socket{ int rs_periodic; /* 0: persistent, 1: periodic (if callhome) */ uint32_t rs_period; /* Period in s (if callhome & periodic) */ uint8_t rs_max_attempts; /* max connect attempts (if callhome) */ - uint16_t rs_idle_timeout; /* Max underlying TCP session remains idle (if callhome and periodic) */ + uint16_t rs_idle_timeout; /* Max underlying TCP session remains idle (if callhome and periodic) (in seconds)*/ uint64_t rs_start; /* First period start, next is start+periods*period */ uint64_t rs_period_nr; /* Dynamic succeeding or timed out periods. Set in restconf_callhome_timer*/ diff --git a/test/test_restconf_callhome.sh b/test/test_restconf_callhome.sh index 24d3adf0..fa4d2fd1 100755 --- a/test/test_restconf_callhome.sh +++ b/test/test_restconf_callhome.sh @@ -40,6 +40,12 @@ clispec=$dir/spec.cli frequest=$dir/frequest # HTTP expected reply server->client +# Duration of time between periodic connections (in seconds) +PERIOD_S=10 + +# Maximum number of seconds the underlying TCP session may remain idle (in seconds) +IDLE_TIMEOUT_S=5 + certdir=$dir/certs cakey=$certdir/ca_key.pem cacert=$certdir/ca_cert.pem @@ -97,8 +103,8 @@ cat < $cfg - 10 - 5 + ${PERIOD_S} + ${IDLE_TIMEOUT_S} @@ -291,7 +297,7 @@ if [ $RC -ne 0 ]; then stop_restconf_pre new "start restconf daemon" - start_restconf -f $cfg -D 1 -l s + start_restconf -f $cfg -D 1 -l s # XXX DONT debug fi new "wait restconf" @@ -302,7 +308,7 @@ expectpart "$(curl $CURLOPTS --key $certdir/andy.key --cert $certdir/andy.crt -X t0=$(date +"%s") new "Send GET via callhome persistence client port 4336" -expectpart "$(${clixon_restconf_callhome_client} -p 4336 -D $DBG -f $frequest -a 127.0.0.1 -c $srvcert -k $srvkey -C $cacert -n 3)" 0 "HTTP/$HVERCH 200" "OK 1" "Close 1 local" "OK 2" "Close 2 local" "OK 3" "Close 3 local" $expectreply --not-- "OK 4" "Close 4" +expectpart "$(${clixon_restconf_callhome_client} -p 4336 -D $DBG -f $frequest -a 127.0.0.1 -c $srvcert -k $srvkey -C $cacert -e 2 -n 3)" 0 "HTTP/$HVERCH 200" "Reply: 1" "Close: 1 local" "Reply: 2" "Close: 2 local" "Reply: 3" "Close: 3 local" $expectreply --not-- "Reply: 4" "Close: 4" t1=$(date +"%s") let t=t1-t0 @@ -313,7 +319,7 @@ fi t0=$(date +"%s") new "Send GET via callhome client periodic port 8336" -expectpart "$(${clixon_restconf_callhome_client} -t 30 -p 8336 -D $DBG -f $frequest -a 127.0.0.1 -c $srvcert -k $srvkey -C $cacert -n 2)" 0 "HTTP/$HVERCH 200" "OK 1" "Close 1" "OK 2" "Close 2" $expectreply --not-- "OK 3" "Close 3" +expectpart "$(${clixon_restconf_callhome_client} -t 30 -p 8336 -D $DBG -f $frequest -a 127.0.0.1 -c $srvcert -k $srvkey -C $cacert -e 2 -n 2)" 0 "HTTP/$HVERCH 200" "Reply: 1" "Close: 1" "Reply: 2" "Close: 2" $expectreply --not-- "Reply: 3" "Close: 3" t1=$(date +"%s") let t=t1-t0 @@ -324,7 +330,7 @@ fi t0=$(date +"%s") new "Send GET via callhome persistence again" -expectpart "$(${clixon_restconf_callhome_client} -p 4336 -D $DBG -f $frequest -a 127.0.0.1 -c $srvcert -k $srvkey -C $cacert -n 3)" 0 "HTTP/$HVERCH 200" "OK 1" "Close 1 local" "OK 2" "Close 2 local" "OK 3" "Close 3 local" $expectreply --not-- "OK 4" "Close 4" +expectpart "$(${clixon_restconf_callhome_client} -p 4336 -D $DBG -f $frequest -a 127.0.0.1 -c $srvcert -k $srvkey -C $cacert -e 2 -n 3)" 0 "HTTP/$HVERCH 200" "Reply: 1" "Close: 1 local" "Reply: 2" "Close: 2 local" "Reply: 3" "Close: 3 local" $expectreply --not-- "Reply: 4" "Close: 4" t1=$(date +"%s") let t=t1-t0 @@ -335,13 +341,26 @@ fi t0=$(date +"%s") new "Send GET: idle-timeout, client keeps socket open, server closes" -expectpart "$(${clixon_restconf_callhome_client} -o -t 60 -p 8336 -D $DBG -f $frequest -a 127.0.0.1 -c $srvcert -k $srvkey -C $cacert -n 1)" 0 "HTTP/$HVERCH 200" "OK 1" $expectreply "Close 1 remote" --not-- "OK 2" "Close 2" +expectpart "$(${clixon_restconf_callhome_client} -t 60 -p 8336 -D 0 -f $frequest -a 127.0.0.1 -c $srvcert -k $srvkey -C $cacert -e 2 -n 2 -i)" 0 "HTTP/$HVERCH 200" "Accept: 1" "Reply: 1" $expectreply "Close: 1 remote" "Accept: 2" "Reply: 2" "Close: 2" --not-- "Accept: 3" t1=$(date +"%s") let t=t1-t0 -new "Check periodic interval ($t) is in interval [5-15]" -if [ $t -lt 5 -o $t -gt 15 ]; then - err1 "timer in interval [5-15] but is: $t" +new "Check periodic interval ($t) is in interval [15-30]" +if [ $t -lt 15 -o $t -gt 30 ]; then + err1 "timer in interval [15-30] but is: $t" +fi + +t0=$(date +"%s") + +new "Send GET: idle-timeout, client sends data then idle, server closes" +expectpart "$(${clixon_restconf_callhome_client} -t 60 -p 8336 -D 0 -f $frequest -a 127.0.0.1 -c $srvcert -k $srvkey -C $cacert -e 2 -n 2 -i -d 3)" 0 "HTTP/$HVERCH 200" "Accept: 1" "Reply: 1" $expectreply "Close: 1 remote" "Accept: 2" "Reply: 2" "Close: 2" --not-- "Accept: 3" + +t1=$(date +"%s") + +let t=t1-t0 +new "Check periodic interval ($t) is in interval [15-30]" +if [ $t -lt 15 -o $t -gt 30 ]; then + err1 "timer in interval [15-30] but is: $t" fi if [ $RC -ne 0 ]; then diff --git a/test/test_restconf_op.sh b/test/test_restconf_op.sh index bf9eeac7..ea832fad 100755 --- a/test/test_restconf_op.sh +++ b/test/test_restconf_op.sh @@ -2,6 +2,7 @@ # Restconf basic functionality # Assume http server setup, such as nginx described in apps/restconf/README.md # Systematic tests of restconf operations GET/POST/PUT/DELETE +# Also multiple requests # See also test_restconf.sh # Magic line must be first in script (see README.md) @@ -205,12 +206,34 @@ new "restconf DELETE whole datastore" expectpart "$(curl $CURLOPTS -X DELETE $RCPROTO://localhost/restconf/data)" 0 "HTTP/$HVER 204" #--------------- Multiple request in single TCP tests +# GET + GET +new "Multiple requests: GET + GET using --next" +expectpart "$(curl $CURLOPTS -H "Accept: application/yang-data+xml" -X GET $RCPROTO://localhost/restconf/data?content=config --next $CURLOPTS -H "Accept: application/yang-data+xml" -X GET $RCPROTO://localhost/restconf/data?content=config)" 0 "HTTP/$HVER 200" "" + +if [ ${HAVE_HTTP1} = true ]; then + new "Multiple requests: GET + GET http/1" + expectpart "$(curl $CURLOPTS --http1.1 -H "Accept: application/yang-data+xml" -X GET $RCPROTO://localhost/restconf/data?content=config --next $CURLOPTS --http1.1 -H "Accept: application/yang-data+xml" -X GET $RCPROTO://localhost/restconf/data?content=config)" 0 "HTTP/1.1 200" "" +fi + +# GET + POST new "Multiple requests: GET + POST using --next" expectpart "$(curl $CURLOPTS -H "Accept: application/yang-data+xml" -X GET $RCPROTO://localhost/restconf/data?content=config --next $CURLOPTS -H "Content-Type: application/yang-data+json" -X POST $RCPROTO://localhost/restconf/data -d '{"example:cont1":{"interface":{"name":"local0","type":"regular"}}}')" 0 "HTTP/$HVER 200" "" "HTTP/$HVER 201" -new "Multiple requests: POST + POST" # XXX Do for HTTP/1 ALSO +if [ ${HAVE_HTTP1} = true ]; then + new "Multiple requests: GET + POST http/1" + expectpart "$(curl $CURLOPTS --http1.1 -H "Accept: application/yang-data+xml" -X GET $RCPROTO://localhost/restconf/data?content=config --next $CURLOPTS --http1.1 -H "Content-Type: application/yang-data+json" -X POST $RCPROTO://localhost/restconf/data -d '{"example:cont1":{"interface":{"name":"local5","type":"regular"}}}')" 0 "HTTP/1.1 200" +fi + +# POST + POST +new "Multiple requests: POST + POST" expectpart "$(curl $CURLOPTS -H "Content-Type: application/yang-data+json" -X POST $RCPROTO://localhost/restconf/data/example:cont1 -d '{"example:interface":{"name":"local1","type":"regular"}}' --next $CURLOPTS -H "Content-Type: application/yang-data+json" -X POST $RCPROTO://localhost/restconf/data/example:cont1 -d '{"example:interface":{"name":"local2","type":"regular"}}')" 0 "HTTP/$HVER 201" "localhost/restconf/data/example:cont1/interface=local1" "localhost/restconf/data/example:cont1/interface=local2" +if [ ${HAVE_HTTP1} = true ]; then + new "Multiple requests: POST + POST http/1" + expectpart "$(curl $CURLOPTS --http1.1 -H "Content-Type: application/yang-data+json" -X POST $RCPROTO://localhost/restconf/data/example:cont1 -d '{"example:interface":{"name":"local7","type":"regular"}}' --next $CURLOPTS --http1.1 -H "Content-Type: application/yang-data+json" -X POST $RCPROTO://localhost/restconf/data/example:cont1 -d '{"example:interface":{"name":"local8","type":"regular"}}')" 0 "HTTP/1.1 201" "localhost/restconf/data/example:cont1/interface=local7" "localhost/restconf/data/example:cont1/interface=local8" + +fi + #--------------- json type tests new "restconf POST type x3 POST" expectpart "$(curl $CURLOPTS -X POST -H "Content-Type: application/yang-data+json" -d '{"example:types":{"tint":42,"tdec64":"42.123","tbool":false,"tstr":"str"}}' $RCPROTO://localhost/restconf/data)" 0 "HTTP/$HVER 201" "Location: $RCPROTO://localhost/restconf/data/example:types" diff --git a/util/clixon_restconf_callhome_client.c b/util/clixon_restconf_callhome_client.c index 68f6086e..e942769c 100644 --- a/util/clixon_restconf_callhome_client.c +++ b/util/clixon_restconf_callhome_client.c @@ -43,6 +43,25 @@ RESTCONF GET to server, then re-waits for new accepts. When accepting a connection, send HTTP data from input or -f tehn wait for reply Reply is matched with -e or printed on stdout + + Tracing events on stdout using: + Accept: at t= # where is connection nr, is time since start of program + Close: at t= # where is connection nr, is local or remote, is time since start of connection + Reply: t= [\n\n] # where is nr data reply from start, is time since start of connection + Exit: # where is which exit point (for debugging) + + Timeline: + w + <--------------> + a0 d0 d1 a1 d0 d1 + ----------|----|----|------------------|----|----|------------------| + + ai Accepted connect from server + di Reply from server + n Number of ai:s, 0 means no limit (_accepts) + D Timeout of di:s (1st request sent at ai, sent back-to-back or with 1sec interval) (_data_timeout_s) + idle? If set do not close after D timeout + t Wait for accept, exit if no accepts (default: 60s), just a safety for deadlocks (_accept_timeout_s) */ #ifdef HAVE_CONFIG_H @@ -68,7 +87,7 @@ /* clixon */ #include "clixon/clixon.h" -#define UTIL_TLS_OPTS "hD:f:F:a:p:c:C:k:n:ot:" +#define UTIL_TLS_OPTS "hD:f:F:a:p:c:C:k:n:N:it:d:e:" #define RESTCONF_CH_TLS 4336 @@ -76,23 +95,45 @@ typedef struct { int ta_ss; /* Accept socket */ SSL_CTX *ta_ctx; /* SSL context */ - FILE *ta_f; /* Input data file */ + struct timeval ta_t0; /* Program start */ } tls_accept_handle; /* User connection-specific data handle */ typedef struct { int sd_s; /* data socket */ SSL *sd_ssl; /* SSL connection data */ + struct timeval sd_t0; /* Start of connection, eg accept call*/ } tls_session_data; -/* Expected connects */ -static int _connects = 1; +/* Lots of global variables here, alt pass them between ta and sd structs + */ +/* Input data file for HTTP request data */ +static FILE *_input_file = NULL; -/* Keep socket open, dont close immediately after reply */ -static int _keep_open = 0; +/* Expected accepts */ +static int _accepts = 1; + +/* Number of accepts */ +static int _n_accepts = 0; + +/* After accepting a socket, a request is sent to the server. The handle the data socket as follows: + * 0: close after first reply + * -1: dont close after reply, (remote side may close) + * s>0: send new requests during seconds after accept, then dont close + */ +static int _idle = 0; /* Timeout in seconds after each accept, if fired just exit */ -static int _timeout_s = 60; +static int _accept_timeout_s = 60; + +/* Timeout of data requests (1st request sent at accept, sent back-to-back / 1sec interval) + * Note: uses blockling timeout 100ms + */ +static int _data_timeout_s = 0; + +/* Event trace, 1: terse (Accept:/Reply:/Close:) 2: full (data payload) */ +static int _event_trace = 0; +static FILE *_event_f = NULL; /* set to stdout in main */ /*! Create and bind stream socket * @param[in] sa Socketaddress @@ -191,6 +232,32 @@ read_data_file(FILE *fe, return retval; } +/*! Read data from file/stdin and write to TLS data socket + */ +static int +tls_write_file(FILE *fp, + SSL *ssl) +{ + int retval = -1; + char *buf = NULL; + size_t len = 0; + int ret; + int sslerr; + + clicon_debug(1, "%s", __FUNCTION__); + if (read_data_file(fp, &buf, &len) < 0) + goto done; + if ((ret = SSL_write(ssl, buf, len)) < 1){ + sslerr = SSL_get_error(ssl, ret); + clicon_debug(1, "%s SSL_write() n:%d errno:%d sslerr:%d", __FUNCTION__, ret, errno, sslerr); + } + retval = 0; + done: + if (buf) + free(buf); + return retval; +} + /*! Client data socket, receive reply from server * Print info on stdout * If keep_open = 0, then close socket directly after 1st reply (client close) @@ -206,54 +273,69 @@ tls_server_reply_cb(int s, char buf[1024]; int n; char *expbuf = NULL; - struct timeval tn; + struct timeval now; struct timeval td; - static int seq = 0; - static struct timeval t0 = {0,}; + static int seq = 0; // from start - clicon_debug(1, "%s", __FUNCTION__); - if (seq == 0) - gettimeofday(&t0, NULL); + // clicon_debug(1, "%s", __FUNCTION__); ssl = sd->sd_ssl; /* get reply & decrypt */ if ((n = SSL_read(ssl, buf, sizeof(buf))) < 0){ clicon_err(OE_XML, errno, "SSL_read"); goto done; } - if (n == 0){ - SSL_shutdown(ssl); + clicon_debug(1, "%s n:%d", __FUNCTION__, n); + gettimeofday(&now, NULL); + timersub(&now, &sd->sd_t0, &td); /* from start of connection */ + if (n == 0){ /* Server closed socket */ SSL_free(ssl); clixon_event_unreg_fd(s, tls_server_reply_cb); - fprintf(stdout, "Close %d remote\n", seq); + if (_event_trace) + fprintf(_event_f, "Close: %d remote at t=%lu\n", _n_accepts, td.tv_sec); close(s); free(sd); - if (_connects == 0) + if (_accepts == 0) ; - else if (_connects == 1) + else if (_accepts == 1){ clixon_exit_set(1); /* XXX more elaborate logic: 1) continue request, 2) close and accept new */ + fprintf(_event_f, "Exit: %s remote\n", __FUNCTION__); + } else - _connects--; + _accepts--; goto ok; } seq++; buf[n] = 0; - gettimeofday(&tn, NULL); - timersub(&tn, &t0, &td); - fprintf(stdout, "OK %d %lu\n%s\n", seq, td.tv_sec, buf); - if (!_keep_open){ + if (_event_trace){ + fprintf(_event_f, "Reply: %d t=%lu\n", seq, td.tv_sec); + if (_event_trace > 1) + fprintf(_event_f, "%s\n", buf); + } + /* See if we should send more requests on this socket */ + if (sd->sd_t0.tv_sec + _data_timeout_s > now.tv_sec){ + /* Send another packet */ + usleep(100000); /* XXX This is a blocking timeout */ + /* Write HTTP request on socket */ + if (tls_write_file(_input_file, sd->sd_ssl) < 0) + goto done; + + } + else if (!_idle){ + clicon_debug(1, "%s idle", __FUNCTION__); SSL_shutdown(ssl); SSL_free(ssl); clixon_event_unreg_fd(s, tls_server_reply_cb); - fprintf(stdout, "Close %d local %lu\n", seq, td.tv_sec); + if (_event_trace) + fprintf(_event_f, "Close: %d local at t=%lu\n", _n_accepts, td.tv_sec); close(s); - if (_connects == 0) + if (_accepts == 0) ; - else if (_connects == 1){ - if (!_keep_open) - clixon_exit_set(1); /* XXX more elaborate logic: 1) continue request, 2) close and accept new */ + else if (_accepts == 1){ + clixon_exit_set(1); /* XXX more elaborate logic: 1) continue request, 2) close and accept new */ + fprintf(_event_f, "Exit: %s idle\n", __FUNCTION__); } else - _connects--; + _accepts--; free(sd); } ok: @@ -261,7 +343,7 @@ tls_server_reply_cb(int s, done: if (expbuf) free(expbuf); - clicon_debug(1, "%s %d", __FUNCTION__, retval); + clicon_debug(1, "%s ret:%d", __FUNCTION__, retval); return retval; } @@ -294,8 +376,8 @@ tls_ssl_init_connect(SSL_CTX *ctx, goto done; } #if 0 - SSL_get0_next_proto_negotiated(conn_.tls.ssl, &next_proto, &next_proto_len); - SSL_get0_alpn_selected(conn_.tls.ssl, &next_proto, &next_proto_len); + SSL_get0_next_proto_negotiated(conn_.tls.ssl, &next_proto, &next_proto_len); + SSL_get0_alpn_selected(conn_.tls.ssl, &next_proto, &next_proto_len); #endif /* perform the connection @@ -334,38 +416,11 @@ tls_ssl_init_connect(SSL_CTX *ctx, return retval; } -/*! Read data from file/stdin and write to TLS data socket - */ -static int -tls_write_file(FILE *fp, - SSL *ssl) -{ - int retval = -1; - char *buf = NULL; - size_t len = 0; - int ret; - int sslerr; - - if (read_data_file(fp, &buf, &len) < 0) - goto done; - if ((ret = SSL_write(ssl, buf, len)) < 1){ - sslerr = SSL_get_error(ssl, ret); - clicon_debug(1, "%s SSL_write() n:%d errno:%d sslerr:%d", __FUNCTION__, ret, errno, sslerr); - } - retval = 0; - done: - if (buf) - free(buf); - return retval; -} - static int tls_timeout_cb(int fd, void *arg) { - tls_accept_handle *ta = (tls_accept_handle *)arg; - - fprintf(stderr, "Timeout(%ds) after accept on socket:%d\n", _timeout_s, ta->ta_ss); + fprintf(_event_f, "Exit: %s\n", __FUNCTION__); exit(200); } @@ -383,7 +438,7 @@ tls_client_timeout(void *arg) clixon_event_unreg_timeout(tls_timeout_cb, arg); /* Set timeout */ gettimeofday(&now, NULL); - t1.tv_sec = _timeout_s; + t1.tv_sec = _accept_timeout_s; timeradd(&now, &t1, &t); if (clixon_event_reg_timeout(t, tls_timeout_cb, @@ -408,6 +463,7 @@ tls_server_accept_cb(int ss, struct sockaddr from = {0,}; socklen_t len; SSL *ssl = NULL; + struct timeval td; clicon_debug(1, "%s", __FUNCTION__); len = sizeof(from); @@ -426,8 +482,14 @@ tls_server_accept_cb(int ss, memset(sd, 0, sizeof(*sd)); sd->sd_s = s; sd->sd_ssl = ssl; - /* Write HTTP request on socket */ - if (tls_write_file(ta->ta_f, ssl) < 0) + gettimeofday(&sd->sd_t0, NULL); + timersub(&sd->sd_t0, &ta->ta_t0, &td); /* from start of connection */ + _n_accepts++; + if (_event_trace) + fprintf(_event_f, "Accept: %d at t=%lu\n", _n_accepts, td.tv_sec); + + /* Always write one HTTP request on socket, maybe more if _data_timeout_s > 0 */ + if (tls_write_file(_input_file, ssl) < 0) goto done; /* register callback for reply */ if (clixon_event_reg_fd(s, tls_server_reply_cb, sd, "tls server reply") < 0) @@ -435,7 +497,6 @@ tls_server_accept_cb(int ss, /* Unregister old + register new timeout */ if (tls_client_timeout(ta) < 0) goto done; - retval = 0; done: return retval; @@ -515,11 +576,14 @@ usage(char *argv0) "\t-C \tcacert\n" "\t-k \tkey\n" "\t-n \tQuit after this many incoming connections, 0 means no limit. Default: 1\n" - "\t-o \tKeep open after receiving first reply. Otherwise close directly after receiving 1st reply\n" - "\t-t \tTimeout in seconds after each accept, if fired just exit. Default: 60s\n" + "\t-t \tTimeout in seconds after each accept, if fired just exit. Default: %ds\n" + "\t-d \tTimeout of data requests on a connection in seconds after each accept, if fired either close or keep idle (see -i). Default: 0s\n" + "\t-i \tIdle after receiving last reply. Otherwise close directly after receiving last reply\n" + "\t-e \tEvent trace on stdout, 1: terse, 2: full\n" , argv0, - RESTCONF_CH_TLS); + RESTCONF_CH_TLS, + _accept_timeout_s); exit(0); } @@ -548,7 +612,6 @@ main(int argc, /* In the startup, logs to stderr & debug flag set later */ clicon_log_init(__FILE__, LOG_INFO, CLICON_LOG_STDERR); - if ((h = clicon_handle_init()) == NULL) goto done; while ((c = getopt(argc, argv, UTIL_TLS_OPTS)) != -1) @@ -593,15 +656,26 @@ main(int argc, case 'n': if (optarg == NULL || *optarg == '-') usage(argv[0]); - _connects = atoi(optarg); + _accepts = atoi(optarg); break; - case 'o': /* keep open, do not close after first reply */ - _keep_open = 1; + case 'i': /* keep open, do not close after first reply */ + _idle = 1; break; - case 't': /* timeout */ + case 't': /* accept timeout */ if (optarg == NULL || *optarg == '-') usage(argv[0]); - _timeout_s = atoi(optarg); + _accept_timeout_s = atoi(optarg); + break; + case 'd': /* data timeout */ + if (optarg == NULL || *optarg == '-') + usage(argv[0]); + _data_timeout_s = atoi(optarg); + break; + case 'e': /* Event trace */ + if (optarg == NULL || *optarg == '-') + usage(argv[0]); + _event_trace = atoi(optarg); + _event_f = stdout; break; default: usage(argv[0]); @@ -614,7 +688,7 @@ main(int argc, clicon_debug_init(dbg, NULL); if (input_filename){ - if ((fp = fopen(input_filename, "r")) == NULL){ + if ((_input_file = fopen(input_filename, "r")) == NULL){ clicon_err(OE_YANG, errno, "open(%s)", input_filename); goto done; } @@ -636,7 +710,7 @@ main(int argc, /* Bind port */ if (callhome_bind(sa, sa_len, 1, &ss) < 0) goto done; - clicon_debug(1, "bind"); + clicon_debug(1, "callhome_bind %s:%hu", addr, port); if ((ta = malloc(sizeof(*ta))) == NULL){ clicon_err(OE_UNIX, errno, "malloc"); goto done; @@ -644,7 +718,7 @@ main(int argc, memset(ta, 0, sizeof(*ta)); ta->ta_ctx = ctx; ta->ta_ss = ss; - ta->ta_f = fp; + gettimeofday(&ta->ta_t0, NULL); if (clixon_event_reg_fd(ss, tls_server_accept_cb, ta, "tls server accept") < 0) goto done; if (tls_client_timeout(ta) < 0)