Fix DNA helper so all tests pass

Added a couple more 'dnahelper' tests for timeout conditions
and spurious output
This commit is contained in:
Andrew Bettison 2012-07-24 11:29:07 +09:30
parent f472ac9a8d
commit 54da59bc56
2 changed files with 102 additions and 32 deletions

View File

@ -85,7 +85,8 @@ static struct sched_ent sched_requests = STRUCT_SCHED_ENT_UNUSED;
static struct sched_ent sched_replies = STRUCT_SCHED_ENT_UNUSED;
static struct sched_ent sched_harvester = STRUCT_SCHED_ENT_UNUSED;
static struct sched_ent sched_errors = STRUCT_SCHED_ENT_UNUSED;
static struct sched_ent schedrestart = STRUCT_SCHED_ENT_UNUSED;
static struct sched_ent sched_restart = STRUCT_SCHED_ENT_UNUSED;
static struct sched_ent sched_timeout = STRUCT_SCHED_ENT_UNUSED;
// This buffer must hold "SID|DID|\n\0"
static char request_buffer[SID_STRLEN + DID_MAXSIZE + 4];
@ -104,6 +105,7 @@ static void monitor_replies(struct sched_ent *alarm);
static void monitor_errors(struct sched_ent *alarm);
static void harvester(struct sched_ent *alarm);
static void restart_delayer(struct sched_ent *alarm);
static void reply_timeout(struct sched_ent *alarm);
static void
dna_helper_close_pipes()
@ -211,6 +213,9 @@ dna_helper_start(const char *command, const char *arg)
sched_requests.poll.fd = -1;
sched_requests.poll.events = POLLOUT;
sched_requests.stats = NULL;
sched_timeout.function = reply_timeout;
sched_timeout.context = NULL;
sched_timeout.stats = NULL;
sched_replies.function = monitor_replies;
sched_replies.context = NULL;
sched_replies.poll.fd = dna_helper_stdout;
@ -238,6 +243,10 @@ dna_helper_start(const char *command, const char *arg)
static int
dna_helper_kill()
{
if (awaiting_reply) {
unschedule(&sched_timeout);
awaiting_reply = 0;
}
if (dna_helper_pid > 0) {
if (debug & DEBUG_DNAHELPER)
DEBUGF("DNAHELPER sending SIGTERM to pid=%d", dna_helper_pid);
@ -262,6 +271,10 @@ dna_helper_harvest(int blocking)
INFOF("DNAHELPER process pid=%u %s", pid, strbuf_str(strbuf_append_exit_status(b, status)));
unschedule(&sched_harvester);
dna_helper_pid = -1;
if (awaiting_reply) {
unschedule(&sched_timeout);
awaiting_reply = 0;
}
return 1;
} else if (pid == -1) {
return WHYF_perror("waitpid(%d, %s)", dna_helper_pid, blocking ? "0" : "WNOHANG");
@ -318,6 +331,8 @@ static void monitor_requests(struct sched_ent *alarm)
INFO("DNAHELPER got SIGPIPE on write -- stopping process");
dna_helper_kill();
} else if (written > 0) {
if (debug & DEBUG_DNAHELPER)
DEBUGF("DNAHELPER wrote request %s", alloca_toprint(-1, request_bufptr, written));
request_bufptr += written;
}
}
@ -325,6 +340,8 @@ static void monitor_requests(struct sched_ent *alarm)
// Request sent successfully. Start watching for reply.
request_bufptr = request_bufend = NULL;
awaiting_reply = 1;
sched_timeout.alarm = overlay_gettime_ms() + 1500;
schedule(&sched_timeout);
}
}
// If no request to send, stop monitoring the helper's stdin pipe.
@ -365,8 +382,8 @@ void handle_reply_line(const char *bufp, size_t len)
if (len == 5 && strncmp(bufp, "DONE\n", 5) == 0) {
if (debug & DEBUG_DNAHELPER)
DEBUG("DNAHELPER reply DONE");
unschedule(&sched_timeout);
awaiting_reply = 0;
// Done
} else {
char sidhex[SID_STRLEN + 1];
char did[DID_MAXSIZE + 1];
@ -490,9 +507,9 @@ static void harvester(struct sched_ent *alarm)
if (debug & DEBUG_DNAHELPER)
DEBUGF("DNAHELPER process died, pausing %d ms before restart", delay_ms);
dna_helper_pid = 0; // Will be set to -1 after delay
schedrestart.function = restart_delayer;
schedrestart.alarm = overlay_gettime_ms() + delay_ms;
schedule(&schedrestart);
sched_restart.function = restart_delayer;
sched_restart.alarm = overlay_gettime_ms() + delay_ms;
schedule(&sched_restart);
}
}
@ -505,6 +522,14 @@ static void restart_delayer(struct sched_ent *alarm)
}
}
static void reply_timeout(struct sched_ent *alarm)
{
if (awaiting_reply) {
WHY("DNAHELPER reply timeout");
dna_helper_kill();
}
}
int
dna_helper_enqueue(overlay_mdp_frame *mdp, const char *did, const unsigned char *requestorSid)
{
@ -539,7 +564,11 @@ dna_helper_enqueue(overlay_mdp_frame *mdp, const char *did, const unsigned char
if (dna_helper_stdin == -1)
return 0;
if (request_bufptr && request_bufptr != request_buffer) {
WARNF("DNAHELPER partially sent request %s -- dropping new request", request_buffer);
WARNF("DNAHELPER currently sending request %s -- dropping new request", request_buffer);
return 0;
}
if (awaiting_reply) {
WARNF("DNAHELPER currently awaiting reply -- dropping new request", request_buffer);
return 0;
}
char buffer[sizeof request_buffer];

View File

@ -44,6 +44,13 @@ configure_servald_server() {
}
setup_dnahelper() {
export SID_JOE_A=1234567890ABCDEF1234567890ABCDEF1234567890ABCDEF1234567890ABCDEA
export SID_JOE_B=1234567890ABCDEF1234567890ABCDEF1234567890ABCDEF1234567890ABCDEB
export SID_JOE_C=1234567890ABCDEF1234567890ABCDEF1234567890ABCDEF1234567890ABCDEC
export SID_JOE_D=1234567890ABCDEF1234567890ABCDEF1234567890ABCDEF1234567890ABCDED
export SID_JOE_E=1234567890ABCDEF1234567890ABCDEF1234567890ABCDEF1234567890ABCDEE
export SID_JOE_F=1234567890ABCDEF1234567890ABCDEF1234567890ABCDEF1234567890ABCDEF
export SID_ECCLES=1234567890ABCDEF1234567890ABCDEF1234567890ABCDEF1234567890ABCDE0
dnahelper="$TFWTMP/dnahelper"
cat >"$dnahelper" <<'EOF'
#!/bin/sh
@ -62,23 +69,27 @@ do
echo "empty DID" >&2
;;
*'|00000|')
# For verification during setup
echo "$token|A|$did|B|"
;;
*'|00001|')
echo "$token|sip://$token@10.1.0.1|$did|Joe A. Bloggs|"
# One valid reply
echo "$token|sip://$SID_JOE_A@10.1.1.1|$did|Joe A. Bloggs|"
;;
*'|00002|')
echo "$token|sip://$token@10.1.0.1|$did|Joe A. Bloggs|"
# Two valid replies
echo "$token|sip://$SID_JOE_A@10.1.1.1|$did|Joe A. Bloggs|"
sleep 0.1
echo "$token|sip://$token@10.1.0.2|$did|Joe B. Bloggs|"
echo "$token|sip://$SID_JOE_B@10.1.1.1|$did|Joe B. Bloggs|"
sleep 0.1
;;
*'|00003|')
echo "$token|sip://$token@10.1.0.1|$did|Joe A. Bloggs|"
# Three valid replies
echo "$token|sip://$SID_JOE_A@10.1.1.1|$did|Joe A. Bloggs|"
sleep 0.1
echo "$token|sip://$token@10.1.0.2|$did|Joe B. Bloggs|"
echo "$token|sip://$SID_JOE_B@10.1.1.1|$did|Joe B. Bloggs|"
sleep 0.1
echo "$token|sip://$token@10.1.0.3|$did|Joe C. Bloggs|"
echo "$token|sip://$SID_JOE_C@10.1.1.1|$did|Joe C. Bloggs|"
sleep 0.1
;;
*'|00004|')
@ -99,59 +110,59 @@ do
;;
*'|000061|')
# Mismatched token
echo "1234567890ABCDEF1234567890ABCDEF1234567890ABCDEF1234567890ABCDEF|did://$token/$did|$did|Eccles|"
echo "$SID_ECCLES|did://$SID_ECCLES/$did|$did|Eccles|"
;;
*'|000062|')
# Empty token
echo "|did://$token/$did|$did|Eccles|"
echo "|did://$SID_ECCLES/$did|$did|Eccles|"
;;
*'|000063|')
# Invalid token (not SID)
echo "1234567890ABCDEF1234567890ABCDEF1234567890ABCDEF1234567890ABCDEX|did://$token/$did|$did|Eccles|"
# Invalid token (not a SID)
echo "1234567890ABCDEF1234567890ABCDEF1234567890ABCDEF1234567890ABCDEX|did://$SID_ECCLES/$did|$did|Eccles|"
;;
*'|000064|')
# Long token
echo "1234567890ABCDEF1234567890ABCDEF1234567890ABCDEF1234567890ABCDEF0|did://$token/$did|$did|Eccles|"
echo "1234567890ABCDEF1234567890ABCDEF1234567890ABCDEF1234567890ABCDEF0|did://$SID_ECCLES/$did|$did|Eccles|"
;;
*'|000065|')
# Short token
echo "1234567890ABCDEF1234567890ABCDEF1234567890ABCDEF1234567890ABCDE|did://$token/$did|$did|Eccles|"
echo "1234567890ABCDEF1234567890ABCDEF1234567890ABCDEF1234567890ABCDE|did://$SID_ECCLES/$did|$did|Eccles|"
;;
*'|000071|')
# Mismatched DID
echo "$token|sip://$token/$did|99999|Eccles|"
echo "$token|sip://$SID_ECCLES/$did|99999|Eccles|"
;;
*'|000072|')
# Empty DID
echo "$token|sip://$token/$did||Eccles|"
echo "$token|sip://$SID_ECCLES/$did||Eccles|"
;;
*'|000073|')
# Invalid DID
echo "$token|sip://$token/$did|9999X|Eccles|"
echo "$token|sip://$SID_ECCLES/$did|9999X|Eccles|"
;;
*'|000074|')
# Long DID
echo "$token|sip://$token/$did|123456789012345678901234567890123|Eccles|"
echo "$token|sip://$SID_ECCLES/$did|123456789012345678901234567890123|Eccles|"
;;
*'|000075|')
# Short DID
echo "$token|sip://$token/$did|9999|Eccles|"
echo "$token|sip://$SID_ECCLES/$did|9999|Eccles|"
;;
*'|000081|')
# Malformed reply, missing final delimiter
echo "$token|sip://$token/$did|9999|Eccles"
echo "$token|sip://$SID_ECCLES/$did|9999|Eccles"
;;
*'|000082|')
# Malformed reply, long name
echo "$token|sip://$token/$did|9999|Abcd efgh ijkl mnop qrst uvwx yzab cdef ghij klmn opqr stuv wxyz abcd efgh ijkl|"
echo "$token|sip://$SID_ECCLES/$did|9999|Abcd efgh ijkl mnop qrst uvwx yzab cdef ghij klmn opqr stuv wxyz abcd efgh ijkl|"
;;
*'|000083|')
# Malformed reply, empty line
echo
;;
*'|000084|')
# Malformed reply, missing \n (so missing "DONE\n" line)
echo -n "$token|sip://$token@10.1.0.1|$did|Joe A. Bloggs|"
# Malformed reply, missing \n (which swallows the following DONE line)
echo -n "$token|sip://$SID_JOE_A@10.1.1.1|$did|Joe A. Bloggs|"
;;
*'|000085|')
# Malformed reply, line too long
@ -170,6 +181,17 @@ do
echo
;;
*'|00009|')
# Take too long to respond
sleep 2
echo "$token|sip://$SID_JOE_D@10.1.1.1|$did|Joe D. Bloggs|"
;;
*'|00010|')
# Spurious output after DONE
echo "$token|sip://$SID_JOE_E@10.1.1.1|$did|Joe E. Bloggs|"
echo DONE
echo "$token|sip://$SID_JOE_F@10.1.1.1|$did|Joe F. Bloggs|"
;;
*'|00011|')
# Die unexpectedly
echo "goodbye cruel world" >&2
exit 42
@ -206,19 +228,19 @@ test_ExecError() {
doc_ReplyOk1="DNA helper returns one valid reply"
test_ReplyOk1() {
executeOk_servald dna lookup 00001
assertStdoutIs -e "sip://$SIDA@10.1.0.1:00001:Joe A. Bloggs\n"
assertStdoutIs -e "sip://$SID_JOE_A@10.1.1.1:00001:Joe A. Bloggs\n"
}
doc_ReplyOk2="DNA helper returns two valid replies"
test_ReplyOk2() {
executeOk_servald dna lookup 00002
assertStdoutIs -e "sip://$SIDA@10.1.0.1:00002:Joe A. Bloggs\nsip://$SIDA@10.1.0.2:00002:Joe B. Bloggs\n"
assertStdoutIs -e "sip://$SID_JOE_A@10.1.1.1:00002:Joe A. Bloggs\nsip://$SID_JOE_B@10.1.1.1:00002:Joe B. Bloggs\n"
}
doc_ReplyOk3="DNA helper returns three valid replies"
test_ReplyOk3() {
executeOk_servald dna lookup 00003
assertStdoutIs -e "sip://$SIDA@10.1.0.1:00003:Joe A. Bloggs\nsip://$SIDA@10.1.0.2:00003:Joe B. Bloggs\nsip://$SIDA@10.1.0.3:00003:Joe C. Bloggs\n"
assertStdoutIs -e "sip://$SID_JOE_A@10.1.1.1:00003:Joe A. Bloggs\nsip://$SID_JOE_B@10.1.1.1:00003:Joe B. Bloggs\nsip://$SID_JOE_C@10.1.1.1:00003:Joe C. Bloggs\n"
}
doc_UriEmpty="DNA helper returns empty URI"
@ -348,14 +370,33 @@ test_ReplyInvalidMissingNewline() {
assertGrep "$LOGA" 'ERROR:.*DNAHELPER.*reply timeout'
}
doc_HelperTimeout="DNA helper process takes too long to reply and is restarted"
test_HelperTimeout() {
executeOk_servald dna lookup 00009
assertStdoutIs ""
assertGrep "$LOGA" 'ERROR:.*DNAHELPER.*reply timeout'
assertGrep "$LOGA" 'INFO:.*DNAHELPER.*process.*terminated by signal 15'
executeOk_servald dna lookup 00001
assertStdoutIs -e "sip://$SID_JOE_A@10.1.1.1:00001:Joe A. Bloggs\n"
}
doc_ReplySpurious="DNA helper spurious output after DONE is ignored"
test_ReplySpurious() {
executeOk_servald dna lookup 00010
assertStdoutIs -e "sip://$SID_JOE_E@10.1.1.1:00010:Joe E. Bloggs\n"
assertGrep "$LOGA" 'WARN:.*DNAHELPER.*spurious output'
executeOk_servald dna lookup 00001
assertStdoutIs -e "sip://$SID_JOE_A@10.1.1.1:00001:Joe A. Bloggs\n"
}
doc_HelperDies="DNA helper process dies unexpectedly and is restarted"
test_HelperDies() {
executeOk_servald dna lookup 00009
executeOk_servald dna lookup 00011
assertStdoutIs ""
assertGrep "$LOGA" 'INFO:.*DNAHELPER.*process.*exited normally with status 42'
assertGrep "$LOGA" 'ERROR:.*DNAHELPER.*"goodbye cruel world\\n"'
executeOk_servald dna lookup 00001
assertStdoutIs -e "sip://$SIDA@10.1.0.1:00001:Joe A. Bloggs\n"
assertStdoutIs -e "sip://$SID_JOE_A@10.1.1.1:00001:Joe A. Bloggs\n"
}
runTests "$@"