Skip to content
Snippets Groups Projects
Commit e204563e authored by Michael Davis's avatar Michael Davis
Browse files

[log_analysis] Renames 'test' directory to 'log_analysis'

parent f354462c
No related branches found
No related tags found
No related merge requests found
# Additional Tests
This directory is for developing test scripts which can be added into CI/pre-production at a later stage.
#!/bin/sh
FILES=$(eos ls /eos/users/test)
for f in ${FILES}
do
eos rm /eos/users/test/$f
done
#!/bin/sh
#
# Preprocess logfiles for more efficient data extraction
# Colours
NC='\033[0m' # No colour
RED='\033[0;31m'
LT_RED='\033[1;31m'
GREEN='\033[0;32m'
LT_GREEN='\033[1;32m'
ORANGE='\033[0;33m'
YELLOW='\033[1;33m'
BLUE='\033[0;34m'
LT_BLUE='\033[1;34m'
echoc()
{
COLOUR=$1
shift
echo -ne "${COLOUR}$*${NC}"
}
process_mgm_log()
{
echoc $LT_BLUE "Extracting log messages from xrdlog.mgm..."
DATE_OFFSET=$(head -1 xrdlog.mgm-20180414 | awk '{ print $1 }')
awk -vDATE_OFFSET="$DATE_OFFSET" '
function processLine(pattern, event, logline) {
gsub("time=.*" pattern, "", logline)
split(logline,logarray)
DAYS=logarray[1]-DATE_OFFSET
HOURS=substr(logarray[2],1,2)
MINS=substr(logarray[2],4,2)
SECS=substr(logarray[2],7,2)
timesecs=((DAYS*24 + HOURS)*60 + MINS)*60 + SECS
print logarray[3],event,timesecs
}
/ default ARCHIVED / { processLine("ARCHIVED", "ARC", $0) }
/ default CLOSEW / { processLine("CLOSEW", "CLO", $0) }
/ default SYNC::CREATE / { processLine("CREATE", "CRE", $0) }
/ default SYNC::PREPARE / { processLine("PREPARE", "PRE", $0) }
/ retrieve_written CLOSEW / { processLine("CLOSEW", "RWC", $0) }
' xrdlog.mgm-20180414 xrdlog.mgm-20180415 >xrdmgm.log.$$
echoc $LT_BLUE "done.\nSorting..."
sort -n xrdmgm.log.$$ >xrdmgm-events.log
echoc $LT_BLUE "done.\n"
rm -f xrdmgm.log.$$
}
process_frontend_log()
{
echoc $LT_BLUE "Extracting archive log messages from cta-frontend..."
FE_HOSTNAME=$(head -1 cta-frontend.log | awk '{ print $4 }')
DATE_OFFSET=$(head -1 cta-frontend.log | awk '{ gsub("^Apr ", "201804"); print $1 }')
awk -vFE_HOSTNAME="$FE_HOSTNAME" -vDATE_OFFSET="$DATE_OFFSET" '
function processLine(event, logline) {
gsub("^Apr ", "201804", logline)
gsub("archiveFileId", "fileId", logline)
gsub(FE_HOSTNAME " .* fileId=\"", "", logline)
gsub("\".*$", "", logline)
split(logline,logarray)
DAYS=logarray[1]-DATE_OFFSET
HOURS=substr(logarray[2],1,2)
MINS=substr(logarray[2],4,2)
SECS=substr(logarray[2],7,2)
timesecs=((DAYS*24 + HOURS)*60 + MINS)*60 + SECS
print logarray[3],event,timesecs
}
/CREATE/ { processLine("CRE", $0) }
/CLOSEW/ { processLine("CLW", $0) }
/PREPARE/ { processLine("PRE", $0) }
' cta-frontend.log >cta-frontend.log.$$
echoc $LT_BLUE "done.\nSorting..."
sort -n cta-frontend.log.$$ >cta-frontend-events.log
echoc $LT_BLUE "done.\n"
rm -f cta-frontend.log.$$
}
process_taped_log()
{
echoc $LT_BLUE "Extracting archive log messages from cta-taped..."
TAPED_HOSTNAME=$(head -1 cta-taped.log | awk '{ print $4 }')
DATE_OFFSET=$(head -1 cta-taped.log | awk '{ gsub("^Apr ", "201804"); print $1 }')
awk -vTAPED_HOSTNAME="$TAPED_HOSTNAME" -vDATE_OFFSET="$DATE_OFFSET" '
function processLine(event, logline) {
gsub("^Apr ", "201804", logline)
gsub(TAPED_HOSTNAME " .* fileId=\"", "", logline)
gsub("\".*$", "", logline)
split(logline,logarray)
DAYS=logarray[1]-DATE_OFFSET
HOURS=substr(logarray[2],1,2)
MINS=substr(logarray[2],4,2)
SECS=substr(logarray[2],7,2)
timesecs=((DAYS*24 + HOURS)*60 + MINS)*60 + SECS
print logarray[3],event,timesecs
}
/In ArchiveMount::getNextJobBatch\(\): popped one job/ { processLine("A_POP", $0) }
/Created tasks for migrating a file/ { processLine("A_TSS", $0) }
/Opened disk file for read/ { processLine("A_OPN", $0) }
/File successfully read from disk/ { processLine("A_RED", $0) }
/File successfully transmitted to drive/ { processLine("A_DNE", $0) }
/Reported to the client a full file archival/ { processLine("A_RPT", $0) }
/In RetrieveMount::getNextJobBatch\(\): popped one job/ { processLine("R_POP", $0) }
/Recall task created/ { processLine("R_TSK", $0) }
/Created tasks for recalling a file/ { processLine("R_RCL", $0) }
/Successfully positioned for reading/ { processLine("R_POS", $0) }
/File successfully read from tape/ { processLine("R_RED", $0) }
/Opened disk file for writing/ { processLine("R_OPN", $0) }
/File successfully transfered to disk/ { processLine("R_TRF", $0) }
' cta-taped.log >cta-taped.log.$$
echoc $LT_BLUE "done.\nSorting..."
sort -n cta-taped.log.$$ >cta-taped-events.log
echoc $LT_BLUE "done.\n"
rm -f cta-taped.log.$$
}
process_mgm_log
#process_frontend_log
#process_taped_log
#!/bin/sh
#
# Test archive, retrieval and deletion of a file
. ./test.conf
##
## Archive
##
FILENAME=file.$$
# Copy small file into EOS
echoc $LT_GREEN "Copying file into EOS..."
eos cp /etc/motd ${EOS_TEST_DIR}/${FILENAME}
echoc $LT_BLUE "\nDisk file info:"
eos fileinfo ${EOS_TEST_DIR}/${FILENAME}
getEOSDiskFileInfo ${EOS_TEST_DIR} ${FILENAME}
echoc $LT_BLUE "EOS Disk ID: $EOS_DISK_ID\nDisk copies: $DISK_COPIES\nTape copies: $TAPE_COPIES\n"
echo_start "\nWaiting for SYNC::CREATE event."
getEOSWFE SYNC::CREATE ${EOS_TEST_DIR}/${FILENAME}
echo_end "done"
echo -e "$LOGLINE\n"
echo_start "Checking CTA Frontend log for CTA Archive ID."
getArchiveID $EOS_DISK_ID
echo_end "done"
echo $LOGLINE
echo_start ARCHIVE_FILE_ID=$ARCHIVE_FILE_ID
echo_end '\n'
echo_start "Waiting for CLOSEW event."
getEOSWFE CLOSEW ${EOS_TEST_DIR}/${FILENAME}
echo_end "done"
echo -e "$LOGLINE\n"
echo_start "Waiting for file to be archived to tape."
getTapeLog $ARCHIVE_FILE_ID 'Reported to the client a full file archival'
echo_end "done"
echo -e "$LOGLINE\n"
echoc $LT_BLUE "List archived file on tape:"
getArchiveFileList ${EOS_DISK_ID}
echo -e "${FILE_LIST}"
echo_start "\nWaiting for ARCHIVED event."
getEOSWFE ARCHIVED ${EOS_TEST_DIR}/${FILENAME}
echo_end "done"
echo -e "$LOGLINE\n"
getEOSDiskFileInfo ${EOS_TEST_DIR} ${FILENAME}
echoc $LT_BLUE "Disk copies: $DISK_COPIES\nTape copies: $TAPE_COPIES\n"
##
## Retrieval
##
echoc $LT_GREEN "Retrieving file from CTA..."
XrdSecPROTOCOL=sss XrdSecSSSKT=/etc/cta/eos.sss.keytab |\
sudo xrdfs root://localhost/ prepare -s "${EOS_TEST_DIR}/${FILENAME}?eos.ruid=${EOS_RUID}"
echo_start "Waiting for SYNC::PREPARE event."
getEOSWFE SYNC::PREPARE ${EOS_TEST_DIR}/${FILENAME}
echo_end "done"
echo -e "$LOGLINE\n"
echo_start "Checking CTA Frontend log for PREPARE event."
getFrontendLog "[Rr]etrieve" $ARCHIVE_FILE_ID
echo_end "done"
echo -e "$LOGLINE\n"
echo_start "Waiting for file to be retrieved from tape."
getTapeLog $ARCHIVE_FILE_ID 'Reported to the client a full file archival' 'File successfully transfered to disk'
echo_end "done"
echo -e "$LOGLINE\n"
getEOSDiskFileInfo ${EOS_TEST_DIR} ${FILENAME}
echoc $LT_BLUE "Disk copies: $DISK_COPIES\nTape copies: $TAPE_COPIES\n"
echoc $LT_GREEN "Copying file out of EOS..."
eos cp ${EOS_TEST_DIR}/${FILENAME} /tmp/${FILENAME}
ls -l /tmp/${FILENAME}
diff /tmp/${FILENAME} /etc/motd
if [ $? -eq 0 ]
then
echoc $LT_GREEN "Files match, OK.\n"
else
error "Files differ."
fi
rm -f /tmp/${FILENAME}
##
## Delete
##
echoc $LT_GREEN "Deleting file from EOS..."
eos rm ${EOS_TEST_DIR}/${FILENAME}
echo_start "Waiting for SYNC::DELETE event."
getEOSWFE SYNC::DELETE ${EOS_TEST_DIR}/${FILENAME}
echo_end "done"
echo -e "$LOGLINE\n"
echo_start "Checking CTA Frontend log for DELETE event."
getFrontendLog "delete" $ARCHIVE_FILE_ID
echo_end "done"
echo -e "$LOGLINE\n"
getEOSDiskFileInfo ${EOS_TEST_DIR} ${FILENAME}
echo -e "${ERRINFO}"
getArchiveFileList ${EOS_DISK_ID}
echo -e "${FILE_LIST}"
# test.conf
#
# Configure your test instance
# System configuration
EOS_INSTANCE=eosdev
EOS_RUID=71761
EOS_TEST_DIR=/eos/users/test
# Location of log files
EOS_MGM_LOG=/var/log/eos/mgm/xrdlog.mgm
CTA_FRONTEND_LOG=/home/cta/cta/cta-frontend.log
CTA_TAPED_LOG=/var/log/cta/cta-taped.log
# Load functions
. ./test.func
# test.func
#
# Functions to inspect logfiles
# Colours
NC='\033[0m' # No colour
RED='\033[0;31m'
LT_RED='\033[1;31m'
GREEN='\033[0;32m'
LT_GREEN='\033[1;32m'
ORANGE='\033[0;33m'
YELLOW='\033[1;33m'
BLUE='\033[0;34m'
LT_BLUE='\033[1;34m'
echo_start()
{
echo -ne ${LT_BLUE}$*
}
echo_end()
{
echo -e $*${NC}
}
echoc()
{
COLOUR=$1
shift
echo -e ${COLOUR}$*${NC}
}
error()
{
echo -ne ${NC}
echo $* >&2
exit 1
}
wait_dot()
{
echo -n "." >&2
sleep 1
}
getArchiveFileList()
{
ERRFILE=/tmp/getArchiveFileListErr.$$
FILE_LIST=$(cta-admin af ls --instance ${EOS_INSTANCE} --diskid ${1} --header 2>${ERRFILE})
[ $? -eq 0 ] || FILE_LIST=$(<${ERRFILE})
rm -f ${ERRFILE}
echo ${FILE_LIST} | grep --quiet "does not exist"
[ $? -eq 0 ] && FILE_LIST="${LT_GREEN}Disk file ${1} has been deleted from CTA.${NC}"
}
getEOSWFE()
{
for i in {1..15}
do
LOGLINE=$(grep " $2 " $EOS_MGM_LOG | grep " $1 ")
[ $? -ne 0 ] || break
wait_dot
done
[ "${LOGLINE}" != "" ] || error "Event $1 $2 not found in ${EOS_MGM_LOG}"
}
getEOSDiskFileInfo()
{
TEST_FILE=${1}/${2}
ERRFILE=/tmp/getEOSDiskFileInfo.$$
FILE_LIST=$(eos ls -y ${TEST_FILE} 2>${ERRFILE})
ERRINFO=$(<${ERRFILE})
rm -f ${ERRFILE}
if [ "$ERRINFO" = "" ]
then
COPIES=$(echo ${FILE_LIST} | awk '{ print $1 }')
DISK_COPIES=$(echo $COPIES | sed 's/^d//' | sed 's/::t.*$//')
TAPE_COPIES=$(echo $COPIES | sed 's/^.*::t//')
DISK_FILE_INFO=$(eos fileinfo ${TEST_FILE})
EOS_DISK_ID=$(echo ${DISK_FILE_INFO} | grep " Fid: " |\
sed 's/^.*Fid: //' | sed 's/ .*$//')
else
echo ${ERRINFO} | grep --quiet "Unable to stat"
[ $? -eq 0 ] && ERRINFO="${LT_GREEN}${2} has been deleted from EOS.${NC}"
fi
}
getArchiveID()
{
for i in {1..15}
do
LOGLINE=$(grep " diskFileID=\"${1}\" " $CTA_FRONTEND_LOG | grep "Queued archive request")
[ $? -ne 0 ] || break
wait_dot
done
[ "${LOGLINE}" != "" ] || error "Queued archive request event for diskFileID=\"${1}\" not found in ${CTA_FRONTEND_LOG}"
ARCHIVE_FILE_ID=$(echo $LOGLINE | sed 's/^.* fileId="//' | sed 's/".*$//')
}
getTapeLog()
{
FILEID=$1
if [ $# -gt 2 ]
then
LAST_MSG=$2
shift
fi
CURRENT_MSG=$2
for i in {1..15}
do
LOGLINE=$(grep " fileId=\"${FILEID}\" " $CTA_TAPED_LOG | grep " LVL=\"Info\" ")
echo $LOGLINE | grep --quiet "${CURRENT_MSG}"
[ $? -ne 0 ] || break
wait_dot
done
[ "${LOGLINE}" != "" ] || error "Archive request fileID=\"${1}\" not found in ${CTA_TAPED_LOG}"
# If this is the retrieve log, delete the archive log items
if [ "${LAST_MSG}" != "" ]
then
LOGLINE=$(echo -e "${LOGLINE}" | awk -v LAST_MSG="${LAST_MSG}" 'BEGIN { is_retrieve = 0; }
is_retrieve { print $0; }
$0 ~ LAST_MSG { is_retrieve = 1; }')
fi
}
getFrontendLog()
{
for i in {1..15}
do
LOGLINE=$(grep " fileId=\"${2}\" " $CTA_FRONTEND_LOG | grep "$1")
[ $? -ne 0 ] || break
wait_dot
done
[ "${LOGLINE}" != "" ] || error "Event $1 fileID=\"${2}\" not found in ${CTA_FRONTEND_LOG}"
}
#!/bin/sh
get_ids()
{
IDS=$(grep -m1 "^$1 " filenameToLogIds.txt)
FILE_ID=$(echo $IDS | cut -d' ' -f2)
ARCHIVE_ID=$(echo $IDS | cut -d' ' -f3)
}
get_mgm_times()
{
TMP_RESULTS=$(grep -m5 "^$1 " xrdmgm-events.log)
TIME_ARCHIVED=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 ARC" | cut -d' ' -f3)
TIME_CLOSEW=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 CLO" | cut -d' ' -f3)
TIME_CREATE=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 CRE" | cut -d' ' -f3)
TIME_PREPARE=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 PRE" | cut -d' ' -f3)
TIME_RETRIEVED=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 RWC" | cut -d' ' -f3)
}
get_frontend_times()
{
TMP_RESULTS=$(grep -m3 "^$1 " cta-frontend-events.log)
TIME_FE_CREATE=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 CRE" | cut -d' ' -f3)
TIME_FE_CLOSEW=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 CLW" | cut -d' ' -f3)
TIME_FE_PREPARE=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 PRE" | cut -d' ' -f3)
}
get_taped_times()
{
# 18 for 2 archive copies + 1 retrieve
TMP_RESULTS=$(grep -m18 "^$1 " cta-taped-events.log)
TIME_TS_ARCHIVE_POP=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 A_POP" | cut -d' ' -f3)
TIME_TS_ARCHIVE_TASKS=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 A_TSS" | cut -d' ' -f3)
TIME_TS_ARCHIVE_OPEN=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 A_OPN" | cut -d' ' -f3)
TIME_TS_ARCHIVE_READ=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 A_RED" | cut -d' ' -f3)
TIME_TS_ARCHIVE_DONE=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 A_DNE" | cut -d' ' -f3)
TIME_TS_ARCHIVE_REPORT=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 A_RPT" | cut -d' ' -f3)
TIME_TS_RETRIEVE_POP=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 R_POP" | cut -d' ' -f3)
TIME_TS_RETRIEVE_TASK=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 R_TSK" | cut -d' ' -f3)
TIME_TS_RETRIEVE_TASKS=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 R_RCL" | cut -d' ' -f3)
TIME_TS_RETRIEVE_POSITION=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 R_POS" | cut -d' ' -f3)
TIME_TS_RETRIEVE_READ=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 R_RED" | cut -d' ' -f3)
TIME_TS_RETRIEVE_OPEN=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 R_OPN" | cut -d' ' -f3)
TIME_TS_RETRIEVE_DONE=$(echo -e "${TMP_RESULTS}" | grep -m1 "^$1 R_TRF" | cut -d' ' -f3)
}
get_offset_time()
{
echo $(($2-$1))
}
get_times()
{
get_ids $1
get_mgm_times $1
get_frontend_times $ARCHIVE_ID
get_taped_times $ARCHIVE_ID
echo -n "$ARCHIVE_ID $FILE_ID "
echo -n "$(get_offset_time $TIME_CREATE $TIME_FE_CREATE) "
echo -n "$(get_offset_time $TIME_FE_CREATE $TIME_CLOSEW) "
echo -n "$(get_offset_time $TIME_CLOSEW $TIME_FE_CLOSEW) "
echo -n "$(get_offset_time $TIME_FE_CLOSEW $TIME_TS_ARCHIVE_POP) "
echo -n "$(get_offset_time $TIME_TS_ARCHIVE_POP $TIME_TS_ARCHIVE_TASKS) "
echo -n "$(get_offset_time $TIME_TS_ARCHIVE_TASKS $TIME_TS_ARCHIVE_OPEN) "
echo -n "$(get_offset_time $TIME_TS_ARCHIVE_OPEN $TIME_TS_ARCHIVE_READ) "
echo -n "$(get_offset_time $TIME_TS_ARCHIVE_READ $TIME_TS_ARCHIVE_DONE) "
echo -n "$(get_offset_time $TIME_TS_ARCHIVE_DONE $TIME_TS_ARCHIVE_REPORT) "
echo -n "$(get_offset_time $TIME_TS_ARCHIVE_REPORT $TIME_ARCHIVED) "
echo -n "$(get_offset_time $TIME_PREPARE $TIME_FE_PREPARE) "
echo -n "$(get_offset_time $TIME_FE_PREPARE $TIME_TS_RETRIEVE_POP) "
echo -n "$(get_offset_time $TIME_TS_RETRIEVE_POP $TIME_TS_RETRIEVE_TASK) "
echo -n "$(get_offset_time $TIME_TS_RETRIEVE_TASK $TIME_TS_RETRIEVE_TASKS) "
echo -n "$(get_offset_time $TIME_TS_RETRIEVE_TASKS $TIME_TS_RETRIEVE_POSITION) "
echo -n "$(get_offset_time $TIME_TS_RETRIEVE_POSITION $TIME_TS_RETRIEVE_READ) "
echo -n "$(get_offset_time $TIME_TS_RETRIEVE_READ $TIME_TS_RETRIEVE_OPEN) "
echo -n "$(get_offset_time $TIME_TS_RETRIEVE_OPEN $TIME_TS_RETRIEVE_DONE) "
echo "$(get_offset_time $TIME_TS_RETRIEVE_DONE $TIME_RETRIEVED);"
}
FILE_NUM=1
echo "cta_times = ["
while :
do
get_times /eos/dev/userfiles/testdir/group_${FILE_NUM}
FILE_NUM=$((${FILE_NUM}+1))
[ $FILE_NUM -le 1000000 ] || break
done
echo "];"
0% Loading or .
You are about to add 0 people to the discussion. Proceed with caution.
Please register or to comment