[pkg-gnupg-maint] Bug#789246: Bug#789246: FTBFS amd64

Wed Jul 8 16:29:13 UTC 2015

On Wed, Jul 08, 2015 at 09:42:14AM -0400, Daniel Kahn Gillmor wrote:
> On Tue 2015-06-30 18:37:05 -0400, Daniel Kahn Gillmor wrote:
> > looking at the test that it seems to hang on (agent/t-protect), i tried
> > running it on my own machine and got the attached strace.  (it completes
> > quickly)
> >
> > we checked with Q_, who looked at the buildd, and it's definitely
> > hanging running agent/t-protect: the process is in R (running) state.
> >
> > agent/t-protect.c is pretty simple, and it's not hanging on other
> > architectures.  I'm perplexed as to why it's not terminating on that
> > platform.
> 
> We managed to get a copy of t-protect from the affected system
> (x86-csail-01) and it runs fine without any delay or hang on other
> systems.  So i suspect the problem is with x86-csail-01 itself.

So if I run the binary there under strace, I see:
16:25:42.599484 select(4, [3], NULL, NULL, {0, 100000}) = 1 (in [3], left {0, 99998})
16:25:42.599556 read(3, "us\t]\267\3102\346\221\377\270\352\26P:\272\252\225\36\316\222\376>f4\2301\370T\nI\200"..., 120) = 120
16:25:42.599640 select(4, [3], NULL, NULL, {0, 100000}) = 1 (in [3], left {0, 99998})
16:25:42.599702 read(3, "\7\5\244H!\311\26\216a \33\222\366D\332\262,: \177,\25\212i\312\300\256Z[\326v\302"..., 120) = 120
16:25:42.599781 select(4, [3], NULL, NULL, {0, 100000}) = 1 (in [3], left {0, 99998})
16:25:42.599843 read(3, "\177\210\346\334$\32\16\220\212\0\373\24\326\354v\352j{6\316\2Z\33\346]\3611\3\335\265um"..., 120) = 120
16:25:42.599922 select(4, [3], NULL, NULL, {0, 100000}) = 1 (in [3], left {0, 99998})
16:25:42.599984 read(3, "\370\rG\335\306L\340J!\346\312\333 \305\353Z\207\302\242\3422\204\261Zn5\337\253\222\353\216\210"..., 120) = 120
16:25:42.600096 gettimeofday({1436372742, 600121}, NULL) = 0
16:25:42.600153 getrusage(RUSAGE_SELF, {ru_utime={0, 0}, ru_stime={0, 0}, ...}) = 0
16:25:42.600211 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {0, 3096700}) = 0
16:25:42.600325 times({tms_utime=0, tms_stime=0, tms_cutime=0, tms_cstime=0}) = 1977487460
16:25:42.600390 gettimeofday({1436372742, 600413}, NULL) = 0
16:25:42.600467 getrusage(RUSAGE_SELF, {ru_utime={0, 0}, ru_stime={0, 0}, ...}) = 0
16:25:42.600530 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {0, 3192053}) = 0
16:25:42.601285 times({tms_utime=0, tms_stime=0, tms_cutime=0, tms_cstime=0}) = 1977487460
16:25:42.601339 times({tms_utime=0, tms_stime=0, tms_cutime=0, tms_cstime=0}) = 1977487460
16:25:42.601393 gettimeofday({1436372742, 601415}, NULL) = 0
16:25:42.601443 getrusage(RUSAGE_SELF, {ru_utime={0, 0}, ru_stime={0, 0}, ...}) = 0
16:25:42.601487 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {0, 3928698}) = 0
16:25:42.603082 times({tms_utime=0, tms_stime=0, tms_cutime=0, tms_cstime=0}) = 1977487460
16:25:42.603136 times({tms_utime=0, tms_stime=0, tms_cutime=0, tms_cstime=0}) = 1977487460
16:25:42.603191 gettimeofday({1436372742, 603215}, NULL) = 0
16:25:42.603244 getrusage(RUSAGE_SELF, {ru_utime={0, 0}, ru_stime={0, 4000}, ...}) = 0
16:25:42.603326 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {0, 5540007}) = 0
16:25:42.606127 times({tms_utime=0, tms_stime=0, tms_cutime=0, tms_cstime=0}) = 1977487460
16:25:42.606184 times({tms_utime=0, tms_stime=0, tms_cutime=0, tms_cstime=0}) = 1977487460
16:25:42.606229 gettimeofday({1436372742, 606245}, NULL) = 0
16:25:42.606273 getrusage(RUSAGE_SELF, {ru_utime={0, 0}, ru_stime={0, 8000}, ...}) = 0
16:25:42.606330 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {0, 8307264}) = 0
16:25:42.612339 times({tms_utime=0, tms_stime=1, tms_cutime=0, tms_cstime=0}) = 1977487461
16:25:42.612417 times({tms_utime=0, tms_stime=1, tms_cutime=0, tms_cstime=0}) = 1977487461
16:25:42.612487 gettimeofday({1436372742, 612505}, NULL) = 0
16:25:42.612531 getrusage(RUSAGE_SELF, {ru_utime={0, 0}, ru_stime={0, 12000}, ...}) = 0
16:25:42.612585 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {0, 14300848}) = 0
16:25:42.623295 times({tms_utime=0, tms_stime=2, tms_cutime=0, tms_cstime=0}) = 1977487462
16:25:42.623356 times({tms_utime=0, tms_stime=2, tms_cutime=0, tms_cstime=0}) = 1977487462
16:25:42.623396 gettimeofday({1436372742, 623409}, NULL) = 0
16:25:42.623430 getrusage(RUSAGE_SELF, {ru_utime={0, 0}, ru_stime={0, 24000}, ...}) = 0
16:25:42.623500 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {0, 24997089}) = 0
16:25:42.643010 times({tms_utime=0, tms_stime=4, tms_cutime=0, tms_cstime=0}) = 1977487464
16:25:42.643058 times({tms_utime=0, tms_stime=4, tms_cutime=0, tms_cstime=0}) = 1977487464
16:25:42.643091 gettimeofday({1436372742, 643104}, NULL) = 0
16:25:42.643123 getrusage(RUSAGE_SELF, {ru_utime={0, 0}, ru_stime={0, 44000}, ...}) = 0
16:25:42.643162 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {0, 44488539}) = 0
16:25:42.643162 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {0, 44488539}) = 0
16:25:42.676690 times({tms_utime=0, tms_stime=7, tms_cutime=0, tms_cstime=0}) = 1977487468
16:25:42.676728 times({tms_utime=0, tms_stime=7, tms_cutime=0, tms_cstime=0}) = 1977487468
16:25:42.676757 gettimeofday({1436372742, 676766}, NULL) = 0
16:25:42.676782 getrusage(RUSAGE_SELF, {ru_utime={0, 0}, ru_stime={0, 76000}, ...}) = 0
16:25:42.676808 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {0, 78005032}) = 0
16:25:42.738303 times({tms_utime=0, tms_stime=13, tms_cutime=0, tms_cstime=0}) = 1977487474
16:25:42.738344 times({tms_utime=0, tms_stime=13, tms_cutime=0, tms_cstime=0}) = 1977487474
16:25:42.738373 gettimeofday({1436372742, 738383}, NULL) = 0
16:25:42.738398 getrusage(RUSAGE_SELF, {ru_utime={0, 0}, ru_stime={0, 136000}, ...}) = 0
16:25:42.738424 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {0, 139491385}) = 0
16:25:42.860323 times({tms_utime=0, tms_stime=26, tms_cutime=0, tms_cstime=0}) = 1977487486
16:25:42.860401 times({tms_utime=0, tms_stime=26, tms_cutime=0, tms_cstime=0}) = 1977487486
16:25:42.860443 gettimeofday({1436372742, 860454}, NULL) = 0
16:25:42.860473 getrusage(RUSAGE_SELF, {ru_utime={0, 0}, ru_stime={0, 260000}, ...}) = 0
16:25:42.860523 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {0, 261410257}) = 0
16:25:43.104555 times({tms_utime=0, tms_stime=50, tms_cutime=0, tms_cstime=0}) = 1977487510
16:25:43.104601 times({tms_utime=0, tms_stime=50, tms_cutime=0, tms_cstime=0}) = 1977487510
16:25:43.104631 gettimeofday({1436372743, 104641}, NULL) = 0
16:25:43.104657 getrusage(RUSAGE_SELF, {ru_utime={0, 0}, ru_stime={0, 504000}, ...}) = 0
16:25:43.104683 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {0, 505428749}) = 0
16:25:43.591533 times({tms_utime=0, tms_stime=99, tms_cutime=0, tms_cstime=0}) = 1977487559
16:25:43.591611 times({tms_utime=0, tms_stime=99, tms_cutime=0, tms_cstime=0}) = 1977487559
16:25:43.591644 gettimeofday({1436372743, 591654}, NULL) = 0
16:25:43.591673 getrusage(RUSAGE_SELF, {ru_utime={0, 0}, ru_stime={0, 992000}, ...}) = 0
16:25:43.591701 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {0, 992255943}) = 0
16:25:44.564538 times({tms_utime=0, tms_stime=196, tms_cutime=0, tms_cstime=0}) = 1977487656
16:25:44.564627 times({tms_utime=0, tms_stime=196, tms_cutime=0, tms_cstime=0}) = 1977487656
16:25:44.564660 gettimeofday({1436372744, 564670}, NULL) = 0
16:25:44.564689 getrusage(RUSAGE_SELF, {ru_utime={0, 0}, ru_stime={1, 964000}, ...}) = 0
16:25:44.564740 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {1, 965043294}) = 0
16:25:46.513466 times({tms_utime=0, tms_stime=391, tms_cutime=0, tms_cstime=0}) = 1977487851
16:25:46.513555 times({tms_utime=0, tms_stime=391, tms_cutime=0, tms_cstime=0}) = 1977487851
16:25:46.513589 gettimeofday({1436372746, 513599}, NULL) = 0
16:25:46.513618 getrusage(RUSAGE_SELF, {ru_utime={0, 0}, ru_stime={3, 912000}, ...}) = 0
16:25:46.513646 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {3, 913653640}) = 0
[...]

And the time between those group of 5 calls doubling each time.

Kurt