strace snippet from a failing Expect 1.31 test on a linux system

strace-expect.log

19152 20:05:49.980597 open("/var/tmp/cpansmoker-1001/1cOTft7OXw/expect_output_file", O_WRONLY|O_CREAT|O_TRUNC, 0666 <unfinished ...>
17757 20:05:49.980629 select(8, [3 5], NULL, NULL, NULL <unfinished ...>
19152 20:05:49.980681 <... open resumed> ) = 4
19152 20:05:49.980709 ioctl(4, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fffd4b52150) = -1 ENOTTY (Inappropriate ioctl for device)
19152 20:05:49.980752 lseek(4, 0, SEEK_CUR) = 0
19152 20:05:49.980791 fstat(4, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
19152 20:05:49.980856 fcntl(4, F_SETFD, FD_CLOEXEC) = 0
19152 20:05:49.980933 write(3, "second\n", 7) = 7
19152 20:05:49.981007 time(NULL)        = 1411070749
19152 20:05:49.981050 time(NULL)        = 1411070749
19152 20:05:49.981105 select(8, [3], NULL, NULL, {3, 0} <unfinished ...>
19157 20:05:49.986704 <... time resumed> [1411070749]) = 1411070749
19157 20:05:49.990708 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
19157 20:05:50.006711 rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
19157 20:05:50.018708 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
19157 20:05:50.030707 nanosleep({1, 0}, 0x7ffffc0eb7b0) = 0
19157 20:05:51.043122 time([1411070751]) = 1411070751
19157 20:05:51.043188 write(1, "tsrif\n", 6) = 6
19152 20:05:51.043249 <... select resumed> ) = 1 (in [3], left {1, 937894})
19157 20:05:51.043324 read(0,  <unfinished ...>
19152 20:05:51.043341 read(3,  <unfinished ...>
19157 20:05:51.043370 <... read resumed> "second\n", 8192) = 7
19152 20:05:51.043387 <... read resumed> "tsrif\n", 2048) = 6
19157 20:05:51.043445 time( <unfinished ...>
19152 20:05:51.043462 write(4, "tsrif\n", 6 <unfinished ...>
19157 20:05:51.043502 <... time resumed> [1411070751]) = 1411070751
19152 20:05:51.043518 <... write resumed> ) = 6
19157 20:05:51.043561 rt_sigprocmask(SIG_BLOCK, [CHLD],  <unfinished ...>
19152 20:05:51.043581 time( <unfinished ...>
19157 20:05:51.043604 <... rt_sigprocmask resumed> [], 8) = 0
19152 20:05:51.043619 <... time resumed> NULL) = 1411070751
19157 20:05:51.043686 rt_sigaction(SIGCHLD, NULL,  <unfinished ...>
19152 20:05:51.043706 select(8, [3], NULL, NULL, {1, 0} <unfinished ...>
19157 20:05:51.043741 <... rt_sigaction resumed> {SIG_DFL, [], 0}, 8) = 0
19157 20:05:51.043784 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
19157 20:05:51.043829 nanosleep({1, 0}, 0x7ffffc0eb7b0) = 0
19152 20:05:52.046857 <... select resumed> ) = 0 (Timeout)
19157 20:05:52.046995 time( <unfinished ...>
19152 20:05:52.047023 open("/var/tmp/cpansmoker-1001/1cOTft7OXw/expect_output_file", O_RDONLY <unfinished ...>
19157 20:05:52.047097 <... time resumed> [1411070752]) = 1411070752
19152 20:05:52.047126 <... open resumed> ) = 5
19157 20:05:52.047184 write(1, "dnoces\n", 7 <unfinished ...>
19152 20:05:52.047216 ioctl(5, SNDCTL_TMR_TIMEBASE or TCGETS <unfinished ...>
19157 20:05:52.047271 <... write resumed> ) = 7
19152 20:05:52.047292 <... ioctl resumed> , 0x7fffd4b52150) = -1 ENOTTY (Inappropriate ioctl for device)
19157 20:05:52.047347 read(0,  <unfinished ...>
19152 20:05:52.047371 lseek(5, 0, SEEK_CUR) = 0
19152 20:05:52.047442 fstat(5, {st_mode=S_IFREG|0644, st_size=6, ...}) = 0
19152 20:05:52.047548 fcntl(5, F_SETFD, FD_CLOEXEC) = 0
19152 20:05:52.047621 fstat(5, {st_mode=S_IFREG|0644, st_size=6, ...}) = 0
19152 20:05:52.047733 read(5, "tsrif\n", 8192) = 6
19152 20:05:52.047807 read(5, "", 8192) = 0
19152 20:05:52.047878 close(5)          = 0
19152 20:05:52.048313 write(6, "not ok 10 - logfile\n", 20) = 20
17757 20:05:52.048369 <... select resumed> ) = 1 (in [3])
19152 20:05:52.048463 write(7, "\n", 1 <unfinished ...>
17757 20:05:52.048485 read(3,  <unfinished ...>
19152 20:05:52.048511 <... write resumed> ) = 1
17757 20:05:52.048524 <... read resumed> "not ok 10 - logfile\n", 65536) = 20