Closed Bug 714406 Opened 14 years ago Closed 14 years ago

runaway autoland processes on cruncher

Categories

(Release Engineering :: General, defect, P2)

Product:
Release Engineering
Component:
General
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED FIXED

People

(Reporter: dustin, Assigned: lsblakk)

Details

(wherein once again I wish that bugzilla had a "PLEASE DO NOT WRAP THIS TEXT" option) root 18122 0.0 0.0 5544 800 ? Ss Jun30 9:35 crond lsblakk 18175 1.6 0.0 6388 1396 ? S 11:20 7:40 \_ crond lsblakk 18180 0.0 0.0 2496 960 ? Ss 11:20 0:00 | \_ /bin/sh -c source /home/lsblakk/autoland-2.6/bin/activate && cd /home/lsblakk/autoland-2.6/tools-git/scripts/autoland && time python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose lsblakk 18188 19.7 0.3 29804 14600 ? R 11:20 93:39 | \_ python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose lsblakk 8970 0.4 0.0 6388 1396 ? S 14:00 1:24 \_ crond lsblakk 8977 0.0 0.0 2496 952 ? Ss 14:00 0:00 | \_ /bin/sh -c source /home/lsblakk/autoland-2.6/bin/activate && cd /home/lsblakk/autoland-2.6/tools-git/scripts/autoland && time python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose lsblakk 8982 9.1 0.4 32920 17892 ? R 14:00 28:52 | \_ python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose lsblakk 22017 0.6 0.0 6388 1396 ? S 15:30 1:22 \_ crond lsblakk 22023 0.0 0.0 2496 952 ? Ss 15:30 0:00 | \_ /bin/sh -c source /home/lsblakk/autoland-2.6/bin/activate && cd /home/lsblakk/autoland-2.6/tools-git/scripts/autoland && time python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose lsblakk 22028 7.5 0.4 33648 18280 ? R 15:30 16:55 | \_ python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose lsblakk 23428 0.3 0.0 6388 1396 ? S 15:40 0:45 \_ crond lsblakk 23429 0.0 0.0 2496 960 ? Ss 15:40 0:00 | \_ /bin/sh -c source /home/lsblakk/autoland-2.6/bin/activate && cd /home/lsblakk/autoland-2.6/tools-git/scripts/autoland && time python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose lsblakk 23438 6.6 0.4 33632 18200 ? R 15:40 14:14 | \_ python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose lsblakk 987 0.3 0.0 6388 1396 ? S 16:50 0:26 \_ crond lsblakk 993 0.0 0.0 2496 956 ? Ss 16:50 0:00 | \_ /bin/sh -c source /home/lsblakk/autoland-2.6/bin/activate && cd /home/lsblakk/autoland-2.6/tools-git/scripts/autoland && time python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose lsblakk 1010 5.4 0.4 33096 17760 ? R 16:50 7:54 | \_ python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose lsblakk 8268 0.2 0.0 6388 1396 ? S 17:40 0:13 \_ crond lsblakk 8274 0.0 0.0 2496 960 ? Ss 17:40 0:00 | \_ /bin/sh -c source /home/lsblakk/autoland-2.6/bin/activate && cd /home/lsblakk/autoland-2.6/tools-git/scripts/autoland && time python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose lsblakk 8281 4.3 0.4 33036 17900 ? R 17:40 4:04 | \_ python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose lsblakk 16784 0.0 0.0 6388 1396 ? S 18:40 0:00 \_ crond lsblakk 16790 0.0 0.0 2496 956 ? Ss 18:40 0:00 | \_ /bin/sh -c source /home/lsblakk/autoland-2.6/bin/activate && cd /home/lsblakk/autoland-2.6/tools-git/scripts/autoland && time python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose lsblakk 16798 0.1 0.4 33632 18508 ? S 18:40 0:02 | \_ python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose basically, seven schedulerDBpoller.py instances, all eating a lot of CPU. strace shows stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2819, ...}) = 0 write(2, "2011-12-30 19:15:41,036 - base_c"..., 97) = 97 gettimeofday({1325301341, 37545}, NULL) = 0 where fd 2 is stderr, a pipe in this case (probably to crond for construction of an email to you, lsblakk). Looks like a lot of logging going on. lsof also shows python 18188 lsblakk 6u IPv4 123098557 TCP unused-10-2-11-247.mozilla.org:52083->unused-10-2-11-247.mozilla.org:amqp (CLOSE_WAIT) python 18188 lsblakk 7u IPv4 123099082 TCP unused-10-2-11-247.mozilla.org:52097->unused-10-2-11-247.mozilla.org:amqp (CLOSE_WAIT) python 18188 lsblakk 8u IPv4 123099513 TCP unused-10-2-11-247.mozilla.org:52106->unused-10-2-11-247.mozilla.org:amqp (CLOSE_WAIT) which suggests that cruncher is running a rabbitmq instance. This might be a separate bug, but that should probably be changed to use rabbit-[a..h].build.mozilla.org instead (with suitable round-robin-reconnect-on-failure behavior in the client). I killed all of the instances.
I just killed them again. I also changed the crontab to run every 30m instead of 10m, in hopes that will quiet this down until someone has a chance to take a look
oh, and here's the unwrapped version of the ps output this time (thanks philor!) 0 loc 1- root@cruncher.build. 2* loc > root 18122 0.0 0.0 5544 760 ? Ss 2011 9:43 crond > lsblakk 23964 1.0 0.0 6388 1392 ? S 2011 23:10 \_ crond > lsblakk 23972 0.0 0.0 2496 940 ? Ss 2011 0:00 | \_ /bin/sh -c source /home/lsblakk/autoland-2.6/bin/activate && cd /home/lsblakk/autoland-2.6/tools-git/scripts/autoland && time python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose > lsblakk 23977 21.2 0.4 33756 17216 ? R 2011 475:58 | \_ python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose > lsblakk 12206 1.4 0.0 6388 1180 ? S 2011 31:29 \_ crond > lsblakk 12212 0.0 0.0 2496 944 ? Ss 2011 0:00 | \_ /bin/sh -c source /home/lsblakk/autoland-2.6/bin/activate && cd /home/lsblakk/autoland-2.6/tools-git/scripts/autoland && time python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose > lsblakk 12217 17.6 0.2 31980 8320 ? R 2011 371:29 | \_ python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose > lsblakk 7628 0.9 0.0 6388 1396 ? S 2011 14:39 \_ crond > lsblakk 7638 0.0 0.0 2496 956 ? Ss 2011 0:00 | \_ /bin/sh -c source /home/lsblakk/autoland-2.6/bin/activate && cd /home/lsblakk/autoland-2.6/tools-git/scripts/autoland && time python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose > lsblakk 7643 11.6 0.3 30004 14904 ? R 2011 173:28 | \_ python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose > lsblakk 10714 0.0 0.0 6388 1396 ? S 2011 0:00 \_ crond > lsblakk 10720 0.0 0.0 2496 960 ? Ss 2011 0:00 | \_ /bin/sh -c source /home/lsblakk/autoland-2.6/bin/activate && cd /home/lsblakk/autoland-2.6/tools-git/scripts/autoland && time python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose > lsblakk 10734 0.0 0.3 28568 13216 ? S 2011 0:09 | \_ python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose > lsblakk 18191 0.4 0.0 6388 1396 ? S 2011 4:03 \_ crond > lsblakk 18203 0.0 0.0 2496 952 ? Ss 2011 0:00 | \_ /bin/sh -c source /home/lsblakk/autoland-2.6/bin/activate && cd /home/lsblakk/autoland-2.6/tools-git/scripts/autoland && time python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose > lsblakk 18209 9.0 0.3 28604 13284 ? R 2011 88:49 | \_ python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose > lsblakk 31643 0.3 0.0 6388 1396 ? S 2011 3:15 \_ crond > lsblakk 31650 0.0 0.0 2496 956 ? Ss 2011 0:00 | \_ /bin/sh -c source /home/lsblakk/autoland-2.6/bin/activate && cd /home/lsblakk/autoland-2.6/tools-git/scripts/autoland && time python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose > lsblakk 31655 7.5 0.3 28604 13356 ? R 2011 67:40 | \_ python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose > lsblakk 12701 0.0 0.0 6388 1396 ? S 2011 0:00 \_ crond > lsblakk 12708 0.0 0.0 2496 956 ? Ss 2011 0:00 | \_ /bin/sh -c source /home/lsblakk/autoland-2.6/bin/activate && cd /home/lsblakk/autoland-2.6/tools-git/scripts/autoland && time python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose > lsblakk 12728 0.0 0.3 28500 13420 ? S 2011 0:08 | \_ python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose > lsblakk 27398 0.4 0.0 6388 1396 ? S 2011 3:13 \_ crond > lsblakk 27399 0.0 0.0 2496 956 ? Ss 2011 0:00 | \_ /bin/sh -c source /home/lsblakk/autoland-2.6/bin/activate && cd /home/lsblakk/autoland-2.6/tools-git/scripts/autoland && time python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose > lsblakk 27409 9.6 0.3 28940 13884 ? R 2011 67:38 | \_ python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose
Given that those are all started in 2011, but that there aren't more, I suspect that the busy-loop in the strace is triggered by a failure condition (rather than the poller just not finishing in 10m). I noticed that the crontab has MAILTO="", so I suspect nobody is getting the failure logs.
Severity: normal → critical
I killed another five instances just now because the / partition was filling up with error logs to email to Lukas (specifically /var/spool/clientmqueue/). The stable version was enabled in cron and the unstable one disabled. >[root@cruncher clientmqueue]# ps auxf | grep lsblakk >lsblakk 3850 1.9 0.0 6388 1396 ? S Jan02 32:30 \_ crond >lsblakk 3856 0.0 0.0 2496 956 ? Ss Jan02 0:00 | \_ /bin/sh -c source /home/lsblakk/autoland-2.6/bin/activate && cd /home/lsblakk/autoland-2.6/tools-git/scripts/autoland && time python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose >lsblakk 3861 24.0 0.4 31124 16104 ? R Jan02 394:10 | \_ python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose >lsblakk 13565 0.6 0.0 6392 1412 ? S 15:30 1:44 \_ crond >lsblakk 13573 0.0 0.0 2496 956 ? Ss 15:30 0:00 | \_ /bin/sh -c source /home/lsblakk/autoland-2.6/bin/activate && cd /home/lsblakk/autoland-2.6/tools-git/scripts/autoland && time python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose >lsblakk 13591 9.5 0.4 34520 19408 ? R 15:30 24:29 | | \_ python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose >lsblakk 13603 0.3 0.0 8664 3008 ? S 15:30 0:50 | \_ /usr/sbin/sendmail -FCronDaemon -i -odi -oem -oi -t >lsblakk 30536 0.7 0.0 6392 1412 ? S 17:30 1:01 \_ crond >lsblakk 30544 0.0 0.0 2496 956 ? Ss 17:30 0:00 | \_ /bin/sh -c source /home/lsblakk/autoland-2.6/bin/activate && cd /home/lsblakk/autoland-2.6/tools-git/scripts/autoland && time python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose >lsblakk 30563 10.7 0.5 35508 20384 ? R 17:30 14:45 | | \_ python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose >lsblakk 30587 0.3 0.0 8664 3004 ? S 17:31 0:30 | \_ /usr/sbin/sendmail -FCronDaemon -i -odi -oem -oi -t >lsblakk 2381 0.2 0.0 6392 1412 ? S 18:00 0:14 \_ crond >lsblakk 2390 0.0 0.0 2496 956 ? Ss 18:00 0:00 | \_ /bin/sh -c source /home/lsblakk/autoland-2.6/bin/activate && cd /home/lsblakk/autoland-2.6/tools-git/scripts/autoland && time python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose >lsblakk 2412 3.2 0.5 34524 19524 ? R 18:00 3:29 | | \_ python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose >lsblakk 2773 0.1 0.0 8664 3000 ? S 18:02 0:07 | \_ /usr/sbin/sendmail -FCronDaemon -i -odi -oem -oi -t >lsblakk 6806 0.0 0.0 6392 1412 ? S 18:30 0:00 \_ crond >lsblakk 6814 0.0 0.0 2496 952 ? Ss 18:30 0:00 | \_ /bin/sh -c source /home/lsblakk/autoland-2.6/bin/activate && cd /home/lsblakk/autoland-2.6/tools-git/scripts/autoland && time python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose >lsblakk 6832 0.0 0.4 34304 19148 ? S 18:30 0:03 | | \_ python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose >lsblakk 6853 0.0 0.0 8664 3004 ? S 18:31 0:00 | \_ /usr/sbin/sendmail -FCronDaemon -i -odi -oem -oi -t >lsblakk 12118 0.0 0.0 2496 960 ? Ss 11:30 0:00 /bin/sh -c source /home/lsblakk/autoland-2.6/bin/activate && cd /home/lsblakk/autoland-2.6/tools-git/scripts/autoland && time python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose >lsblakk 12123 12.0 0.4 31952 16804 ? R 11:30 60:07 \_ python schedulerDBpoller.py -b try -c schedulerdb_config.ini -u None -p None --verbose On inspection, there were a lot of lines like this: [RabbitMQ] Failed connection to localhost, retry in 60s followed by millions of lines like 2012-01-03 19:10:36,546 - base_connection - _handle_error - BlockingConnection: Socket is closed I don't know the architecture of autoland at all, but it does look like there are some issues with error handling. Is a single schedulerDBpoller.py supposed to run at intervals ? If so you can guard it with lockfile. Eg cd $HOME/some_dir && lockfile -10 -r 5 poller.lock 2> /dev/null && (<run autoland>; rm -rf poller.lock) That'll try to get a lockfile 5 times, 10 seconds apart, and not run the process if it can't create the lock file poller.lock (eg if an earlier call is still running).
Priority: -- → P2
I have removed the rabbit queue and put in a lockfile as well as restarted sendmail so I believe this issue to be taken care of now.
Status: NEW → RESOLVED
Closed: 14 years ago
Resolution: --- → FIXED
Product: mozilla.org → Release Engineering
You need to log in before you can comment on or make changes to this bug.