66db3fb64ca38726355efb68c340c93fd83282bb max Mon Sep 14 05:33:23 2026 -0700 uniprot otto: the run watcher could never see a run end notifyRun.sh decided whether a run was still going with pgrep -f "doUniprot run" which matches far more than the pipeline: the shell that launched the watcher carries that string in its own command line and stays alive for as long as the watcher does, and so does every status command anyone types. The test was therefore true forever. The watcher started on 9 September sat in its loop through a failure on 11 September and three days of nothing, never reached the code that reports the outcome, and never sent the mail it exists to send. Its log was empty the whole time, which looked exactly like healthy silence. Both process searches are now restricted to the user the pipeline runs as, otto by default and overridable as the fourth argument. Measured against the live process list: the old pattern matched 5 processes where there is 1 run, the new one matches exactly 1. refs #38300 diff --git src/hg/utils/otto/uniprot/notifyRun.sh src/hg/utils/otto/uniprot/notifyRun.sh index 4de2fe28166..c7b926d2765 100755 --- src/hg/utils/otto/uniprot/notifyRun.sh +++ src/hg/utils/otto/uniprot/notifyRun.sh @@ -35,53 +35,60 @@ send() { subject=$1 slackSend "$subject" { echo "run directory: $dir" echo "started: $started" echo "now: `date '+%Y-%m-%d %H:%M:%S'`" echo echo "last runLog.txt lines:" tail -5 $dir/runLog.txt 2>/dev/null echo echo "last log lines:" grep -a " - " $log 2>/dev/null | tail -12 } | mail -s "uniprot otto: $subject" "$to" } +# The pipeline runs as otto, from cron and from a hand-started doUpdate.sh. Restrict every +# process search to that user: a bare "pgrep -f doUniprot run" also matches the shell that +# launched this watcher and every status command someone types, so it can never see the run +# end. That is not hypothetical, it is how this watcher sat believing a run was in progress +# for three days and never mailed the failure it was there to report. +runUser=${4:-otto} + # Work out which stage the log has reached. Later matches win, so the order is the order # the pipeline goes through. stageOf() { s="starting up" grep -aq "Downloading NCBI gene2refseq" $log 2>/dev/null && s="downloading the NCBI gene2refseq file" grep -aq "lftp ftp" $log 2>/dev/null && s="mirroring UniProt from expasy" grep -aq "Moving files from" $log 2>/dev/null && s="download finished, moving files into place" grep -aq "not newer than file in" $log 2>/dev/null && s="no new UniProt release, nothing to do" grep -aq "Converting uniprot XML" $log 2>/dev/null && s="parsing the SwissProt XML" # doUniprot's run() logs its "Running: ..." line only after the command returns, so the # log cannot tell us that the TrEMBL parse has started, only that it has finished. # Ask the process table instead, and fall back to the log once the process is gone. - { pgrep -f "uniprotToTab.*--trembl" > /dev/null 2>&1 || grep -aq -- "--trembl" $log 2>/dev/null; } \ + { pgrep -u "$runUser" -f "uniprotToTab.*--trembl" > /dev/null 2>&1 || grep -aq -- "--trembl" $log 2>/dev/null; } \ && s="parsing the TrEMBL XML, this is the multi-day part" grep -aq "checking/creating pslMap" $log 2>/dev/null && s="parse done, building the protein-to-genome mappings on the cluster" grep -aq "Wrote release string" $log 2>/dev/null && s="writing version files and flipping the bigBeds" grep -aq "Archive: Copied" $log 2>/dev/null && s="copying to the hgdownload archive" grep -aq "Uniprot pipeline completed" $log 2>/dev/null && s="finished" echo "$s" } running() { - pgrep -f "doUniprot run" > /dev/null 2>&1 + pgrep -u "$runUser" -f "doUniprot run" > /dev/null 2>&1 } if ! running ; then echo "No doUniprot run in progress, nothing to watch." exit 1 fi started=`date '+%Y-%m-%d %H:%M:%S'` stage=`stageOf` lastMail=`date +%s` send "run being watched, now $stage" while running ; do sleep $poll now=`stageOf`