The branch main has been updated by markj: URL: https://cgit.FreeBSD.org/src/commit/?id=560c22937ba96e8bab57de395dcf340ecf8d6794
commit 560c22937ba96e8bab57de395dcf340ecf8d6794 Author: Mark Johnston <[email protected]> AuthorDate: 2026-01-22 15:50:25 +0000 Commit: Mark Johnston <[email protected]> CommitDate: 2026-01-22 15:50:25 +0000 syslogd/tests: Address races I occasionally see failures in the syslogd test suite. The problem is that the tests are racy: they send a message using logger(1), then immediately check whether the message was logged to a log file. If the syslogd instance under test doesn't get a chance to run before the second step, the test fails. This change reworks things to avoid the race while minimizing the amount of time sleeping. 1) Each test uses a single logfile, so have them use a new common variable, SYSLOGD_LOGFILE, instead of something test-specific. 2) In syslogd_start(), if the configuration references SYSLOGD_LOGFILE, wait for it to be created by syslogd before returning. 3) Add a helper syslogd_check_log(), to check for a given log entry in the last line of SYSLOGD_LOGFILE, instead of using atf_check directly. 4) In syslogd_check_log(), poll the logfile until the desired log entry appears, or the test times out. With this change, I was able to run the tests 1000 times in a loop with 4-way parallelism without seeing any test failures. Without the change I usually get a failure within 10 loops. Reviewed by: jlduran MFC after: 2 weeks Differential Revision: https://reviews.freebsd.org/D54779 --- .../syslogd/tests/syslogd_basic_format_test.sh | 28 +-- .../syslogd/tests/syslogd_format_test_common.sh | 1 - .../syslogd/tests/syslogd_forwarded_format_test.sh | 42 ++-- .../syslogd/tests/syslogd_relayed_format_test.sh | 30 +-- usr.sbin/syslogd/tests/syslogd_test.sh | 241 ++++++++++----------- usr.sbin/syslogd/tests/syslogd_test_common.sh | 33 +++ 6 files changed, 184 insertions(+), 191 deletions(-) diff --git a/usr.sbin/syslogd/tests/syslogd_basic_format_test.sh b/usr.sbin/syslogd/tests/syslogd_basic_format_test.sh index 09477a568ba8..219c3e045676 100644 --- a/usr.sbin/syslogd/tests/syslogd_basic_format_test.sh +++ b/usr.sbin/syslogd/tests/syslogd_basic_format_test.sh @@ -11,9 +11,8 @@ setup_basic_format_test() { local format="$1" - local logfile="$2" - printf "user.debug\t${logfile}\n" > "${SYSLOGD_CONFIG}" + printf "user.debug\t${SYSLOGD_LOGFILE}\n" > "${SYSLOGD_CONFIG}" syslogd_start \ -O "${format}" \ @@ -33,11 +32,10 @@ O_flag_bsd_basic_head() O_flag_bsd_basic_body() { local format="bsd" - local logfile="${PWD}/O_flag_${format}_basic.log" - setup_basic_format_test "${format}" "${logfile}" + setup_basic_format_test "${format}" - atf_check -s exit:0 -o match:"${REGEX_RFC3164_LOGFILE}" cat "${logfile}" + syslogd_check_log "${REGEX_RFC3164_LOGFILE}" } O_flag_bsd_basic_cleanup() { @@ -52,11 +50,10 @@ O_flag_rfc3164_basic_head() O_flag_rfc3164_basic_body() { local format="rfc3164" - local logfile="${PWD}/O_flag_${format}_basic.log" - setup_basic_format_test "${format}" "${logfile}" + setup_basic_format_test "${format}" - atf_check -s exit:0 -o match:"${REGEX_RFC3164_LOGFILE}" cat "${logfile}" + syslogd_check_log "${REGEX_RFC3164_LOGFILE}" } O_flag_rfc3164_basic_cleanup() { @@ -71,11 +68,10 @@ O_flag_rfc3164strict_basic_head() O_flag_rfc3164strict_basic_body() { local format="rfc3164-strict" - local logfile="${PWD}/O_flag_${format}_basic.log" - setup_basic_format_test "${format}" "${logfile}" + setup_basic_format_test "${format}" - atf_check -s exit:0 -o match:"${REGEX_RFC3164_LOGFILE}" cat "${logfile}" + syslogd_check_log "${REGEX_RFC3164_LOGFILE}" } O_flag_rfc3164strict_basic_cleanup() { @@ -90,11 +86,10 @@ O_flag_syslog_basic_head() O_flag_syslog_basic_body() { local format="syslog" - local logfile="${PWD}/O_flag_${format}_basic.log" - setup_basic_format_test "${format}" "${logfile}" + setup_basic_format_test "${format}" - atf_check -s exit:0 -o match:"${REGEX_RFC5424_LOGFILE}" cat "${logfile}" + syslogd_check_log "${REGEX_RFC5424_LOGFILE}" } O_flag_syslog_basic_cleanup() { @@ -109,11 +104,10 @@ O_flag_rfc5424_basic_head() O_flag_rfc5424_basic_body() { local format="rfc5424" - local logfile="${PWD}/O_flag_${format}_basic.log" - setup_basic_format_test "${format}" "${logfile}" + setup_basic_format_test "${format}" - atf_check -s exit:0 -o match:"${REGEX_RFC5424_LOGFILE}" cat "${logfile}" + syslogd_check_log "${REGEX_RFC5424_LOGFILE}" } O_flag_rfc5424_basic_cleanup() { diff --git a/usr.sbin/syslogd/tests/syslogd_format_test_common.sh b/usr.sbin/syslogd/tests/syslogd_format_test_common.sh index 995bb048881b..99623015c15d 100644 --- a/usr.sbin/syslogd/tests/syslogd_format_test_common.sh +++ b/usr.sbin/syslogd/tests/syslogd_format_test_common.sh @@ -55,7 +55,6 @@ confirm_INET_support_or_skip() set_common_atf_metadata() { - atf_set timeout 5 atf_set require.user root } diff --git a/usr.sbin/syslogd/tests/syslogd_forwarded_format_test.sh b/usr.sbin/syslogd/tests/syslogd_forwarded_format_test.sh index b17627a935c8..db607a33d093 100644 --- a/usr.sbin/syslogd/tests/syslogd_forwarded_format_test.sh +++ b/usr.sbin/syslogd/tests/syslogd_forwarded_format_test.sh @@ -14,8 +14,7 @@ SERVER_2_PORT="5141" setup_forwarded_format_test() { local format="$1" - local logfile="$2" - local pcapfile="$3" + local pcapfile="$2" confirm_INET_support_or_skip @@ -25,7 +24,7 @@ setup_forwarded_format_test() tcpdump_pid="$!" # Start first server: receive UDP, log to file - printf "user.debug\t${logfile}\n" > "$(config_filename ${SERVER_1_PORT})" + printf "user.debug\t${SYSLOGD_LOGFILE}\n" > "$(config_filename ${SERVER_1_PORT})" syslogd_start_on_port "${SERVER_1_PORT}" -O "${format}" # Start second server: send UDP, log to first server @@ -49,14 +48,13 @@ O_flag_bsd_forwarded_head() O_flag_bsd_forwarded_body() { local format="bsd" - local logfile="${PWD}/${format}_forwarded.log" local pcapfile="${PWD}/${format}_forwarded.pcap" - setup_forwarded_format_test "${format}" "${logfile}" "${pcapfile}" + setup_forwarded_format_test "${format}" "${pcapfile}" atf_expect_fail \ "PR 220246 syslog -O bsd deviates from RFC 3164 recommendations" - atf_check -s exit:0 -o match:"${REGEX_RFC3164_LOGFILE}" cat "${logfile}" + syslogd_check_log "${REGEX_RFC3164_LOGFILE}" atf_check -s exit:0 -e ignore -o match:"${REGEX_RFC3164_PAYLOAD}" \ tcpdump -A -r "${pcapfile}" } @@ -76,14 +74,13 @@ O_flag_rfc3164_forwarded_head() O_flag_rfc3164_forwarded_body() { local format="rfc3164" - local logfile="${PWD}/${format}_forwarded.log" local pcapfile="${PWD}/${format}_forwarded.pcap" - setup_forwarded_format_test "${format}" "${logfile}" "${pcapfile}" + setup_forwarded_format_test "${format}" "${pcapfile}" atf_expect_fail \ "PR 220246 syslog -O rfc3164 deviates from RFC 3164 recommendations" - atf_check -s exit:0 -o match:"${REGEX_RFC3164_LOGFILE}" cat "${logfile}" + syslogd_check_log "${REGEX_RFC3164_LOGFILE}" atf_check -s exit:0 -e ignore -o match:"${REGEX_RFC3164_PAYLOAD}" \ tcpdump -A -r "${pcapfile}" } @@ -103,12 +100,11 @@ O_flag_rfc3164strict_forwarded_head() O_flag_rfc3164strict_forwarded_body() { local format="rfc3164-strict" - local logfile="${PWD}/${format}_forwarded.log" local pcapfile="${PWD}/${format}_forwarded.pcap" - setup_forwarded_format_test "${format}" "${logfile}" "${pcapfile}" + setup_forwarded_format_test "${format}" "${pcapfile}" - atf_check -s exit:0 -o match:"${REGEX_RFC3164_LOGFILE}" cat "${logfile}" + syslogd_check_log "${REGEX_RFC3164_LOGFILE}" atf_check -s exit:0 -e ignore -o match:"${REGEX_RFC3164_PAYLOAD}" \ tcpdump -A -r "${pcapfile}" } @@ -128,12 +124,11 @@ O_flag_syslog_forwarded_head() O_flag_syslog_forwarded_body() { local format="syslog" - local logfile="${PWD}/${format}_forwarded.log" local pcapfile="${PWD}/${format}_forwarded.pcap" - setup_forwarded_format_test "${format}" "${logfile}" "${pcapfile}" + setup_forwarded_format_test "${format}" "${pcapfile}" - atf_check -s exit:0 -o match:"${REGEX_RFC5424_LOGFILE}" cat "${logfile}" + syslogd_check_log "${REGEX_RFC5424_LOGFILE}" atf_check -s exit:0 -e ignore -o match:"${REGEX_RFC5424_PAYLOAD}" \ tcpdump -A -r "${pcapfile}" } @@ -153,12 +148,11 @@ O_flag_rfc5424_forwarded_head() O_flag_rfc5424_forwarded_body() { local format="rfc5424" - local logfile="${PWD}/${format}_forwarded.log" local pcapfile="${PWD}/${format}_forwarded.pcap" - setup_forwarded_format_test "${format}" "${logfile}" "${pcapfile}" + setup_forwarded_format_test "${format}" "${pcapfile}" - atf_check -s exit:0 -o match:"${REGEX_RFC5424_LOGFILE}" cat "${logfile}" + syslogd_check_log "${REGEX_RFC5424_LOGFILE}" atf_check -s exit:0 -e ignore -o match:"${REGEX_RFC5424_PAYLOAD}" \ tcpdump -A -r "${pcapfile}" } @@ -180,13 +174,11 @@ O_flag_bsd_forwarded_legacy_head() O_flag_bsd_forwarded_legacy_body() { local format="bsd" - local logfile="${PWD}/${format}_forwarded_legacy.log" local pcapfile="${PWD}/${format}_forwarded.pcap" - setup_forwarded_format_test "${format}" "${logfile}" "${pcapfile}" + setup_forwarded_format_test "${format}" "${pcapfile}" - atf_check -s exit:0 -o match:"${REGEX_RFC3164_LEGACY_LOGFILE}" \ - cat "${logfile}" + syslogd_check_log "${REGEX_RFC3164_LEGACY_LOGFILE}" atf_check -s exit:0 -e ignore \ -o match:"${REGEX_RFC3164_LEGACY_PAYLOAD}" \ tcpdump -A -r "${pcapfile}" @@ -208,13 +200,11 @@ O_flag_rfc3164_forwarded_legacy_head() O_flag_rfc3164_forwarded_legacy_body() { local format="rfc3164" - local logfile="${PWD}/${format}_forwarded_legacy.log" local pcapfile="${PWD}/${format}_forwarded.pcap" - setup_forwarded_format_test "${format}" "${logfile}" "${pcapfile}" + setup_forwarded_format_test "${format}" "${pcapfile}" - atf_check -s exit:0 -o match:"${REGEX_RFC3164_LEGACY_LOGFILE}" \ - cat "${logfile}" + syslogd_check_log "${REGEX_RFC3164_LEGACY_LOGFILE}" atf_check -s exit:0 -e ignore \ -o match:"${REGEX_RFC3164_LEGACY_PAYLOAD}" \ tcpdump -A -r "${pcapfile}" diff --git a/usr.sbin/syslogd/tests/syslogd_relayed_format_test.sh b/usr.sbin/syslogd/tests/syslogd_relayed_format_test.sh index d3e0db4e0f1c..6a5aeba77a25 100644 --- a/usr.sbin/syslogd/tests/syslogd_relayed_format_test.sh +++ b/usr.sbin/syslogd/tests/syslogd_relayed_format_test.sh @@ -15,8 +15,7 @@ readonly SERVER_3_PORT="5142" setup_relayed_format_test() { local format="$1" - local logfile="$2" - local pcapfile="$3" + local pcapfile="$2" confirm_INET_support_or_skip @@ -26,7 +25,7 @@ setup_relayed_format_test() tcpdump_pid="$!" # Start first (central) server: receive UDP, log to file - printf "user.debug\t${logfile}\n" \ + printf "user.debug\t${SYSLOGD_LOGFILE}\n" \ > "$(config_filename ${SERVER_1_PORT})" syslogd_start_on_port "${SERVER_1_PORT}" -O "${format}" @@ -56,13 +55,12 @@ O_flag_bsd_relayed_head() O_flag_bsd_relayed_body() { local format="bsd" - local logfile="${PWD}/${format}_relayed.log" local pcapfile="${PWD}/${format}_relayed.pcap" - setup_relayed_format_test "${format}" "${logfile}" "${pcapfile}" + setup_relayed_format_test "${format}" "${pcapfile}" atf_expect_fail "PR 220246 issue with the legacy bsd format" - atf_check -s exit:0 -o match:"${REGEX_RFC3164_LOGFILE}" cat "${logfile}" + syslogd_check_log "${REGEX_RFC3164_LOGFILE}" atf_check -s exit:0 -e ignore -o match:"${REGEX_RFC3164_PAYLOAD}" \ tcpdump -A -r "${pcapfile}" } @@ -83,13 +81,12 @@ O_flag_rfc3164_relayed_head() O_flag_rfc3164_relayed_body() { local format="rfc3164" - local logfile="${PWD}/${format}_relayed.log" local pcapfile="${PWD}/${format}_relayed.pcap" - setup_relayed_format_test "${format}" "${logfile}" "${pcapfile}" + setup_relayed_format_test "${format}" "${pcapfile}" atf_expect_fail "PR 220246 issue with the legacy rfc3164 format" - atf_check -s exit:0 -o match:"${REGEX_RFC3164_LOGFILE}" cat "${logfile}" + syslogd_check_log "${REGEX_RFC3164_LOGFILE}" atf_check -s exit:0 -e ignore -o match:"${REGEX_RFC3164_PAYLOAD}" \ tcpdump -A -r "${pcapfile}" } @@ -110,12 +107,11 @@ O_flag_rfc3164strict_relayed_head() O_flag_rfc3164strict_relayed_body() { local format="rfc3164-strict" - local logfile="${PWD}/${format}_relayed.log" local pcapfile="${PWD}/${format}_relayed.pcap" - setup_relayed_format_test "${format}" "${logfile}" "${pcapfile}" + setup_relayed_format_test "${format}" "${pcapfile}" - atf_check -s exit:0 -o match:"${REGEX_RFC3164_LOGFILE}" cat "${logfile}" + syslogd_check_log "${REGEX_RFC3164_LOGFILE}" atf_check -s exit:0 -e ignore -o match:"${REGEX_RFC3164_PAYLOAD}" \ tcpdump -A -r "${pcapfile}" } @@ -136,12 +132,11 @@ O_flag_syslog_relayed_head() O_flag_syslog_relayed_body() { local format="syslog" - local logfile="${PWD}/${format}_relayed.log" local pcapfile="${PWD}/${format}_relayed.pcap" - setup_relayed_format_test "${format}" "${logfile}" "${pcapfile}" + setup_relayed_format_test "${format}" "${pcapfile}" - atf_check -s exit:0 -o match:"${REGEX_RFC5424_LOGFILE}" cat "${logfile}" + syslogd_check_log "${REGEX_RFC5424_LOGFILE}" atf_check -s exit:0 -e ignore -o match:"${REGEX_RFC5424_PAYLOAD}" \ tcpdump -A -r "${pcapfile}" } @@ -162,12 +157,11 @@ O_flag_rfc5424_relayed_head() O_flag_rfc5424_relayed_body() { local format="rfc5424" - local logfile="${PWD}/${format}_relayed.log" local pcapfile="${PWD}/${format}_relayed.pcap" - setup_relayed_format_test "${format}" "${logfile}" "${pcapfile}" + setup_relayed_format_test "${format}" "${pcapfile}" - atf_check -s exit:0 -o match:"${REGEX_RFC5424_LOGFILE}" cat "${logfile}" + syslogd_check_log "${REGEX_RFC5424_LOGFILE}" atf_check -s exit:0 -e ignore -o match:"${REGEX_RFC5424_PAYLOAD}" \ tcpdump -A -r "${pcapfile}" } diff --git a/usr.sbin/syslogd/tests/syslogd_test.sh b/usr.sbin/syslogd/tests/syslogd_test.sh index fbe390d93aae..d43473eac12d 100644 --- a/usr.sbin/syslogd/tests/syslogd_test.sh +++ b/usr.sbin/syslogd/tests/syslogd_test.sh @@ -23,15 +23,12 @@ unix_head() } unix_body() { - local logfile="${PWD}/unix.log" - - printf "user.debug\t${logfile}\n" > "${SYSLOGD_CONFIG}" + printf "user.debug\t${SYSLOGD_LOGFILE}\n" > "${SYSLOGD_CONFIG}" syslogd_start syslogd_log -p user.debug -t unix -h "${SYSLOGD_LOCAL_SOCKET}" \ "hello, world (unix)" - atf_check -s exit:0 -o match:"unix: hello, world \(unix\)" \ - tail -n 1 "${logfile}" + syslogd_check_log "unix: hello, world \(unix\)" } unix_cleanup() { @@ -45,19 +42,16 @@ inet_head() } inet_body() { - local logfile="${PWD}/inet.log" - [ "$(sysctl -n kern.features.inet)" != "1" ] && atf_skip "Kernel does not support INET" - printf "user.debug\t${logfile}\n" > "${SYSLOGD_CONFIG}" + printf "user.debug\t${SYSLOGD_LOGFILE}\n" > "${SYSLOGD_CONFIG}" syslogd_start # We have INET transport; make sure we can use it. syslogd_log -4 -p user.debug -t inet -h 127.0.0.1 -P "${SYSLOGD_UDP_PORT}" \ "hello, world (v4)" - atf_check -s exit:0 -o match:"inet: hello, world \(v4\)" \ - tail -n 1 "${logfile}" + syslogd_check_log "inet: hello, world \(v4\)" } inet_cleanup() { @@ -71,19 +65,16 @@ inet6_head() } inet6_body() { - local logfile="${PWD}/inet6.log" - [ "$(sysctl -n kern.features.inet6)" != "1" ] && atf_skip "Kernel does not support INET6" - printf "user.debug\t${logfile}\n" > "${SYSLOGD_CONFIG}" + printf "user.debug\t${SYSLOGD_LOGFILE}\n" > "${SYSLOGD_CONFIG}" syslogd_start # We have INET6 transport; make sure we can use it. syslogd_log -6 -p user.debug -t unix -h ::1 -P "${SYSLOGD_UDP_PORT}" \ "hello, world (v6)" - atf_check -s exit:0 -o match:"unix: hello, world \(v6\)" \ - tail -n 1 "${logfile}" + syslogd_check_log "unix: hello, world \(v6\)" } inet6_cleanup() { @@ -97,25 +88,24 @@ reload_head() } reload_body() { - logfile="${PWD}/reload.log" - printf "user.debug\t/${logfile}\n" > "${SYSLOGD_CONFIG}" + printf "user.debug\t${SYSLOGD_LOGFILE}\n" > "${SYSLOGD_CONFIG}" syslogd_start syslogd_log -p user.debug -t reload -h "${SYSLOGD_LOCAL_SOCKET}" \ "pre-reload" - atf_check -s exit:0 -o match:"reload: pre-reload" tail -n 1 "${logfile}" + syslogd_check_log "reload: pre-reload" # Override the old rule. - truncate -s 0 "${logfile}" - printf "news.debug\t${logfile}\n" > "${SYSLOGD_CONFIG}" + printf "news.debug\t${SYSLOGD_LOGFILE}\n" > "${SYSLOGD_CONFIG}" syslogd_reload syslogd_log -p user.debug -t reload -h "${SYSLOGD_LOCAL_SOCKET}" \ "post-reload user" syslogd_log -p news.debug -t reload -h "${SYSLOGD_LOCAL_SOCKET}" \ "post-reload news" - atf_check -s exit:0 -o not-match:"reload: post-reload user" cat ${logfile} - atf_check -s exit:0 -o match:"reload: post-reload news" cat ${logfile} + sleep 0.5 + syslogd_check_log_nopoll "reload: post-reload news" + syslogd_check_log_nomatch "reload: post-reload user" } reload_cleanup() { @@ -129,30 +119,36 @@ prog_filter_head() } prog_filter_body() { - logfile="${PWD}/prog_filter.log" - printf "!prog1,prog2\nuser.debug\t${logfile}\n" > "${SYSLOGD_CONFIG}" + printf "!prog1,prog2\nuser.debug\t${SYSLOGD_LOGFILE}\n" > "${SYSLOGD_CONFIG}" syslogd_start - for i in 1 2 3; do - syslogd_log -p user.debug -t "prog${i}" -h "${SYSLOGD_LOCAL_SOCKET}" \ - "hello this is prog${i}" - done - atf_check -s exit:0 -o match:"prog1: hello this is prog1" cat "${logfile}" - atf_check -s exit:0 -o match:"prog2: hello this is prog2" cat "${logfile}" - atf_check -s exit:0 -o not-match:"prog3: hello this is prog3" cat "${logfile}" + syslogd_log -p user.debug -t "prog1" -h "${SYSLOGD_LOCAL_SOCKET}" \ + "hello this is prog1" + syslogd_check_log "prog1: hello this is prog1" + + syslogd_log -p user.debug -t "prog2" -h "${SYSLOGD_LOCAL_SOCKET}" \ + "hello this is prog2" + syslogd_check_log "prog2: hello this is prog2" + + syslogd_log -p user.debug -t "prog3" -h "${SYSLOGD_LOCAL_SOCKET}" \ + "hello this is prog3" + syslogd_check_log_nomatch "prog3: hello this is prog3" # Override the old rule. - truncate -s 0 ${logfile} - printf "!-prog1,prog2\nuser.debug\t${logfile}\n" > "${SYSLOGD_CONFIG}" + printf "!-prog1,prog2\nuser.debug\t${SYSLOGD_LOGFILE}\n" > "${SYSLOGD_CONFIG}" syslogd_reload - for i in 1 2 3; do - syslogd_log -p user.debug -t "prog${i}" -h "${SYSLOGD_LOCAL_SOCKET}" \ - "hello this is prog${i}" - done - atf_check -s exit:0 -o not-match:"prog1: hello this is prog1" cat "${logfile}" - atf_check -s exit:0 -o not-match:"prog2: hello this is prog2" cat "${logfile}" - atf_check -s exit:0 -o match:"prog3: hello this is prog3" cat "${logfile}" + syslogd_log -p user.debug -t "prog1" -h "${SYSLOGD_LOCAL_SOCKET}" \ + "hello this is prog1" + syslogd_check_log_nomatch "prog1: hello this is prog1" + + syslogd_log -p user.debug -t "prog2" -h "${SYSLOGD_LOCAL_SOCKET}" \ + "hello this is prog2" + syslogd_check_log_nomatch "prog2: hello this is prog2" + + syslogd_log -p user.debug -t "prog3" -h "${SYSLOGD_LOCAL_SOCKET}" \ + "hello this is prog3" + syslogd_check_log "prog3: hello this is prog3" } prog_filter_cleanup() { @@ -166,30 +162,32 @@ host_filter_head() } host_filter_body() { - logfile="${PWD}/host_filter.log" - printf "+host1,host2\nuser.debug\t${logfile}\n" > "${SYSLOGD_CONFIG}" + printf "+host1,host2\nuser.debug\t${SYSLOGD_LOGFILE}\n" > "${SYSLOGD_CONFIG}" syslogd_start - for i in 1 2 3; do - syslogd_log -p user.debug -t "host${i}" -H "host${i}" \ - -h "${SYSLOGD_LOCAL_SOCKET}" "hello this is host${i}" - done - atf_check -s exit:0 -o match:"host1: hello this is host1" cat "${logfile}" - atf_check -s exit:0 -o match:"host2: hello this is host2" cat "${logfile}" - atf_check -s exit:0 -o not-match:"host3: hello this is host3" cat "${logfile}" + syslogd_log -p user.debug -t "host1" -H "host1" \ + -h "${SYSLOGD_LOCAL_SOCKET}" "hello this is host1" + syslogd_check_log "host1: hello this is host1" + syslogd_log -p user.debug -t "host2" -H "host2" \ + -h "${SYSLOGD_LOCAL_SOCKET}" "hello this is host2" + syslogd_check_log "host2: hello this is host2" + syslogd_log -p user.debug -t "host3" -H "host3" \ + -h "${SYSLOGD_LOCAL_SOCKET}" "hello this is host3" + syslogd_check_log_nomatch "host3: hello this is host3" # Override the old rule. - truncate -s 0 ${logfile} - printf "\-host1,host2\nuser.debug\t${logfile}\n" > "${SYSLOGD_CONFIG}" + printf "\-host1,host2\nuser.debug\t${SYSLOGD_LOGFILE}\n" > "${SYSLOGD_CONFIG}" syslogd_reload - for i in 1 2 3; do - syslogd_log -p user.debug -t "host${i}" -H "host${i}" \ - -h "${SYSLOGD_LOCAL_SOCKET}" "hello this is host${i}" - done - atf_check -s exit:0 -o not-match:"host1: hello this is host1" cat "${logfile}" - atf_check -s exit:0 -o not-match:"host2: hello this is host2" cat "${logfile}" - atf_check -s exit:0 -o match:"host3: hello this is host3" cat "${logfile}" + syslogd_log -p user.debug -t "host1" -H "host1" \ + -h "${SYSLOGD_LOCAL_SOCKET}" "hello this is host1" + syslogd_check_log_nomatch "host1: hello this is host1" + syslogd_log -p user.debug -t "host2" -H "host2" \ + -h "${SYSLOGD_LOCAL_SOCKET}" "hello this is host2" + syslogd_check_log_nomatch "host2: hello this is host2" + syslogd_log -p user.debug -t "host3" -H "host3" \ + -h "${SYSLOGD_LOCAL_SOCKET}" "hello this is host3" + syslogd_check_log "host3: hello this is host3" } host_filter_cleanup() { @@ -203,47 +201,43 @@ prop_filter_head() } prop_filter_body() { - logfile="${PWD}/prop_filter.log" - printf ":msg,contains,\"FreeBSD\"\nuser.debug\t${logfile}\n" \ + printf ":msg,contains,\"FreeBSD\"\nuser.debug\t${SYSLOGD_LOGFILE}\n" \ > "${SYSLOGD_CONFIG}" syslogd_start syslogd_log -p user.debug -t "prop1" -h "${SYSLOGD_LOCAL_SOCKET}" "FreeBSD" syslogd_log -p user.debug -t "prop2" -h "${SYSLOGD_LOCAL_SOCKET}" "freebsd" - atf_check -s exit:0 -o match:"prop1: FreeBSD" cat "${logfile}" - atf_check -s exit:0 -o not-match:"prop2: freebsd" cat "${logfile}" + syslogd_check_log "prop1: FreeBSD" + syslogd_check_log_nomatch "prop2: freebsd" - truncate -s 0 ${logfile} - printf ":msg,!contains,\"FreeBSD\"\nuser.debug\t${logfile}\n" \ + printf ":msg,!contains,\"FreeBSD\"\nuser.debug\t${SYSLOGD_LOGFILE}\n" \ > "${SYSLOGD_CONFIG}" syslogd_reload syslogd_log -p user.debug -t "prop1" -h "${SYSLOGD_LOCAL_SOCKET}" "FreeBSD" syslogd_log -p user.debug -t "prop2" -h "${SYSLOGD_LOCAL_SOCKET}" "freebsd" - atf_check -s exit:0 -o not-match:"prop1: FreeBSD" cat "${logfile}" - atf_check -s exit:0 -o match:"prop2: freebsd" cat "${logfile}" + syslogd_check_log_nomatch "prop1: FreeBSD" + syslogd_check_log "prop2: freebsd" - truncate -s 0 ${logfile} - printf ":msg,icase_contains,\"FreeBSD\"\nuser.debug\t${logfile}\n" \ + printf ":msg,icase_contains,\"FreeBSD\"\nuser.debug\t${SYSLOGD_LOGFILE}\n" \ > "${SYSLOGD_CONFIG}" syslogd_reload syslogd_log -p user.debug -t "prop1" -h "${SYSLOGD_LOCAL_SOCKET}" "FreeBSD" + syslogd_check_log "prop1: FreeBSD" syslogd_log -p user.debug -t "prop2" -h "${SYSLOGD_LOCAL_SOCKET}" "freebsd" - atf_check -s exit:0 -o match:"prop1: FreeBSD" cat "${logfile}" - atf_check -s exit:0 -o match:"prop2: freebsd" cat "${logfile}" + syslogd_check_log "prop2: freebsd" - truncate -s 0 ${logfile} - printf ":msg,!icase_contains,\"FreeBSD\"\nuser.debug\t${logfile}\n" \ + printf ":msg,!icase_contains,\"FreeBSD\"\nuser.debug\t${SYSLOGD_LOGFILE}\n" \ > "${SYSLOGD_CONFIG}" syslogd_reload syslogd_log -p user.debug -t "prop1" -h "${SYSLOGD_LOCAL_SOCKET}" "FreeBSD" syslogd_log -p user.debug -t "prop2" -h "${SYSLOGD_LOCAL_SOCKET}" "freebsd" syslogd_log -p user.debug -t "prop3" -h "${SYSLOGD_LOCAL_SOCKET}" "Solaris" - atf_check -s exit:0 -o not-match:"prop1: FreeBSD" cat "${logfile}" - atf_check -s exit:0 -o not-match:"prop2: freebsd" cat "${logfile}" - atf_check -s exit:0 -o match:"prop3: Solaris" cat "${logfile}" + syslogd_check_log_nomatch "prop1: FreeBSD" + syslogd_check_log_nomatch "prop2: freebsd" + syslogd_check_log "prop3: Solaris" } prop_filter_cleanup() { @@ -258,13 +252,12 @@ host_action_head() host_action_body() { local addr="192.0.2.100" - local logfile="${PWD}/host_action.log" atf_check ifconfig lo1 create atf_check ifconfig lo1 inet "${addr}/24" atf_check ifconfig lo1 up - printf "user.debug\t${logfile}\n" > "${SYSLOGD_CONFIG}" + printf "user.debug\t${SYSLOGD_LOGFILE}\n" > "${SYSLOGD_CONFIG}" syslogd_start -b "${addr}" printf "user.debug\t@${addr}\n" > "${SYSLOGD_CONFIG}.2" @@ -276,8 +269,7 @@ host_action_body() syslogd_log -p user.debug -t "test" -h "${SYSLOGD_LOCAL_SOCKET}.2" \ "message from syslogd2" - atf_check -s exit:0 -o match:"test: message from syslogd2" \ - cat "${logfile}" + syslogd_check_log "test: message from syslogd2" } host_action_cleanup() { @@ -296,17 +288,17 @@ pipe_action_head() } pipe_action_body() { - logfile="${PWD}/pipe_action.log" printf "\"While I'm digging in the tunnel, the elves will often come to me \ - with solutions to my problem.\"\n-Saymore Crey" > ${logfile} + with solutions to my problem.\"\n-Saymore Crey" > testfile printf "!pipe\nuser.debug\t| sed -i '' -e 's/Saymore Crey/Seymour Cray/g' \ - ${logfile}\n" > "${SYSLOGD_CONFIG}" + testfile\n" > "${SYSLOGD_CONFIG}" syslogd_start syslogd_log -p user.debug -t "pipe" -h "${SYSLOGD_LOCAL_SOCKET}" \ "fix spelling error" - atf_check -s exit:0 -o match:"Seymour Cray" cat "${logfile}" + sleep 0.5 + atf_check -o match:"Seymour Cray" cat testfile } pipe_action_cleanup() { @@ -320,16 +312,15 @@ pipe_action_reload_head() } pipe_action_reload_body() { - local logfile="${PWD}/pipe_reload.log" local pipecmd="${PWD}/pipe_cmd.sh" cat <<__EOF__ > "${pipecmd}" #!/bin/sh -echo START > ${logfile} +echo START > ${SYSLOGD_LOGFILE} while read msg; do - echo \${msg} >> ${logfile} + echo \${msg} >> ${SYSLOGD_LOGFILE} done -echo END >> ${logfile} +echo END >> ${SYSLOGD_LOGFILE} exit 0 __EOF__ chmod +x "${pipecmd}" @@ -338,8 +329,9 @@ __EOF__ syslogd_start syslogd_log -p user.debug -t "pipe" -h "${SYSLOGD_LOCAL_SOCKET}" "MSG" - syslogd_reload - atf_check -s exit:0 -o match:"END" tail -n 1 "${logfile}" + atf_check pkill -HUP -F "${1:-${SYSLOGD_PIDFILE}}" + sleep 0.1 + syslogd_check_log_nopoll "END" } pipe_action_reload_cleanup() { @@ -354,17 +346,14 @@ jail_noinet_head() } jail_noinet_body() { - local logfile - syslogd_mkjail syslogd_noinet - logfile="${PWD}/jail_noinet.log" - printf "user.debug\t${logfile}\n" > "${SYSLOGD_CONFIG}" + printf "user.debug\t${SYSLOGD_LOGFILE}\n" > "${SYSLOGD_CONFIG}" syslogd_start -j syslogd_noinet -s -s syslogd_log -p user.debug -t "test" -h "${SYSLOGD_LOCAL_SOCKET}" \ "hello, world" - atf_check -s exit:0 -o match:"test: hello, world" cat "${logfile}" + syslogd_check_log "test: hello, world" } jail_noinet_cleanup() { @@ -410,26 +399,25 @@ allowed_peer_head() } allowed_peer_body() { - local logfile - allowed_peer_test_setup - logfile="${PWD}/jail.log" - printf "user.debug\t${logfile}\n" > "${SYSLOGD_CONFIG}" + printf "user.debug\t${SYSLOGD_LOGFILE}\n" > "${SYSLOGD_CONFIG}" syslogd_start -j syslogd_allowed_peer -b 169.254.0.1:514 -a '169.254.0.2/32' # Make sure that a message from 169.254.0.2:514 is logged. syslogd_log_jail syslogd_client \ - -p user.debug -t test1 -h 169.254.0.1 -S 169.254.0.2:514 "hello, world" - atf_check -o match:"test1: hello, world" cat "${logfile}" + -p user.debug -t test1 -h 169.254.0.1 -S 169.254.0.2:514 "hello, world" + syslogd_check_log "test1: hello, world" # ... but not a message from port 515. syslogd_log_jail syslogd_client \ - -p user.debug -t test2 -h 169.254.0.1 -S 169.254.0.2:515 "hello, world" - atf_check -o not-match:"test2: hello, world" cat "${logfile}" + -p user.debug -t test2 -h 169.254.0.1 -S 169.254.0.2:515 "hello, world" + sleep 0.5 + syslogd_check_log_nomatch "test2: hello, world" syslogd_log_jail syslogd_client \ - -p user.debug -t test2 -h 169.254.0.1 -S 169.254.0.3:515 "hello, world" - atf_check -o not-match:"test2: hello, world" cat "${logfile}" + -p user.debug -t test2 -h 169.254.0.1 -S 169.254.0.3:515 "hello, world" + sleep 0.5 + syslogd_check_log_nomatch "test2: hello, world" syslogd_stop @@ -438,10 +426,10 @@ allowed_peer_body() syslogd_log_jail syslogd_client \ -p user.debug -t test3 -h 169.254.0.1 -S 169.254.0.2:514 "hello, world" - atf_check -o not-match:"test3: hello, world" cat "${logfile}" + syslogd_check_log_nomatch "test3: hello, world" syslogd_log_jail syslogd_client \ -p user.debug -t test4 -h 169.254.0.1 -S 169.254.0.2:515 "hello, world" - atf_check -o match:"test4: hello, world" cat "${logfile}" + syslogd_check_log "test4: hello, world" syslogd_stop } @@ -458,16 +446,13 @@ allowed_peer_forwarding_head() } allowed_peer_forwarding_body() { - local logfile - allowed_peer_test_setup printf "user.debug\[email protected]\n" > client_config printf "mark.debug\[email protected]:515\n" >> client_config syslogd_start -j syslogd_client -b 169.254.0.2:514 -f ${PWD}/client_config - logfile="${PWD}/jail.log" - printf "+169.254.0.2\nuser.debug\t${logfile}\n" > "${SYSLOGD_CONFIG}" + printf "+169.254.0.2\nuser.debug\t${SYSLOGD_LOGFILE}\n" > "${SYSLOGD_CONFIG}" syslogd_start -j syslogd_allowed_peer -P ${SYSLOGD_PIDFILE}.2 \ -b 169.254.0.1:514 -a 169.254.0.2/32 @@ -478,8 +463,8 @@ allowed_peer_forwarding_body() syslogd_log_jail syslogd_client \ -h 169.254.0.2 -p mark.debug -t test2 "hello, world" - atf_check -o match:"test1: hello, world" cat "${logfile}" - atf_check -o not-match:"test2: hello, world" cat "${logfile}" + syslogd_check_log "test1: hello, world" + syslogd_check_log_nomatch "test2: hello, world" } allowed_peer_forwarding_cleanup() { @@ -494,29 +479,28 @@ allowed_peer_wildcard_head() } allowed_peer_wildcard_body() { - local logfile - allowed_peer_test_setup - logfile="${PWD}/jail.log" - printf "user.debug\t${logfile}\n" > "${SYSLOGD_CONFIG}" + printf "user.debug\t${SYSLOGD_LOGFILE}\n" > "${SYSLOGD_CONFIG}" syslogd_start -j syslogd_allowed_peer -b 169.254.0.1:514 -a '169.254.0.2/32:*' # Make sure that a message from 169.254.0.2:514 is logged. syslogd_log_jail syslogd_client \ -p user.debug -t test1 -h 169.254.0.1 -S 169.254.0.2:514 "hello, world" - atf_check -o match:"test1: hello, world" cat "${logfile}" + syslogd_check_log "test1: hello, world" + # ... as is a message from 169.254.0.2:515, allowed by the wildcard. syslogd_log_jail syslogd_client \ -p user.debug -t test2 -h 169.254.0.1 -S 169.254.0.2:515 "hello, world" - atf_check -o match:"test2: hello, world" cat "${logfile}" + syslogd_check_log "test2: hello, world" + # ... but not a message from 169.254.0.3. syslogd_log_jail syslogd_client \ -p user.debug -t test3 -h 169.254.0.1 -S 169.254.0.3:514 "hello, world" - atf_check -o not-match:"test3: hello, world" cat "${logfile}" + syslogd_check_log_nomatch "test3: hello, world" syslogd_log_jail syslogd_client \ -p user.debug -t test3 -h 169.254.0.1 -S 169.254.0.3:515 "hello, world" - atf_check -o not-match:"test3: hello, world" cat "${logfile}" + syslogd_check_log_nomatch "test3: hello, world" syslogd_stop } @@ -533,9 +517,9 @@ forward_head() } forward_body() { - syslogd_check_req epair + local epair - local epair logfile + syslogd_check_req epair atf_check -o save:epair ifconfig epair create epair=$(cat epair) @@ -558,11 +542,10 @@ mail.debug @169.254.0.2 ftp.debug @169.254.0.1 __EOF__ - logfile="${PWD}/jail.log" cat <<__EOF__ > ./server_config -user.debug ${logfile} -mail.debug ${logfile} -ftp.debug ${logfile} +user.debug ${SYSLOGD_LOGFILE} +mail.debug ${SYSLOGD_LOGFILE} +ftp.debug ${SYSLOGD_LOGFILE} __EOF__ syslogd_start -j syslogd_server -f ${PWD}/server_config -b 169.254.0.1 -b 169.254.0.2 @@ -570,15 +553,15 @@ __EOF__ syslogd_log_jail syslogd_client \ -h 169.254.0.3 -P $SYSLOGD_UDP_PORT -p user.debug -t test1 "hello, world" - atf_check -o match:"test1: hello, world" cat "${logfile}" + syslogd_check_log "test1: hello, world" syslogd_log_jail syslogd_client \ -h 169.254.0.3 -P $SYSLOGD_UDP_PORT -p mail.debug -t test2 "you've got mail" - atf_check -o match:"test2: you've got mail" cat "${logfile}" + syslogd_check_log "test2: you've got mail" syslogd_log_jail syslogd_client \ -h 169.254.0.3 -P $SYSLOGD_UDP_PORT -p ftp.debug -t test3 "transfer complete" - atf_check -o match:"test3: transfer complete" cat "${logfile}" + syslogd_check_log "test3: transfer complete" } forward_cleanup() { diff --git a/usr.sbin/syslogd/tests/syslogd_test_common.sh b/usr.sbin/syslogd/tests/syslogd_test_common.sh index 87e9080d99ca..a4aea07f8528 100644 --- a/usr.sbin/syslogd/tests/syslogd_test_common.sh +++ b/usr.sbin/syslogd/tests/syslogd_test_common.sh @@ -15,6 +15,7 @@ readonly SYSLOGD_CONFIG="${PWD}/syslog.conf" readonly SYSLOGD_LOCAL_SOCKET="${PWD}/log.sock" readonly SYSLOGD_PIDFILE="${PWD}/syslogd.pid" readonly SYSLOGD_LOCAL_PRIVSOCKET="${PWD}/logpriv.sock" +readonly SYSLOGD_LOGFILE="${PWD}/log" # Start a private syslogd instance. syslogd_start() @@ -83,6 +84,11 @@ syslogd_start() & # Give syslogd a bit of time to spin up. + if grep -q "[[:space:]]${SYSLOGD_LOGFILE}$" "${conf_file:-${SYSLOGD_CONFIG}}"; then + while [ ! -f "${SYSLOGD_LOGFILE}" ]; do + sleep 0.1 + done + fi while [ "$((i+=1))" -le 20 ]; do [ -S "${socket:-${SYSLOGD_LOCAL_SOCKET}}" ] && return sleep 0.1 @@ -106,7 +112,9 @@ syslogd_log_jail() # Make syslogd reload its configuration file. syslogd_reload() { + atf_check truncate -s 0 ${SYSLOGD_LOGFILE} atf_check pkill -HUP -F "${1:-${SYSLOGD_PIDFILE}}" + sleep 0.1 } # Stop a private syslogd instance. @@ -165,3 +173,28 @@ syslogd_cleanup() ifconfig $(cat epair) destroy fi } + +# Check the last entry in the log file for a given message. +syslogd_check_log_nopoll() +{ + local msg=$1 + + atf_check -o match:"${msg}" tail -n 1 "${SYSLOGD_LOGFILE}" +} + +# Same as above, but first wait for syslogd to write to the log file. +syslogd_check_log() +{ + local msg=$1 + + atf_check -r 10 -o match:"${msg}" tail -n 1 "${SYSLOGD_LOGFILE}" +} + +# Make sure no log entry matching the given message exists. +syslogd_check_log_nomatch() +{ + local msg=$1 + + sleep 0.5 + atf_check -o not-match:"${msg}" cat "${SYSLOGD_LOGFILE}" +}
