Attachment "F022e.small" to
ticket [462317ffff]
added by
kogorman
2001-09-18 23:17:13.
[snippage ... but leaving the events around the last select() call with a nonzero timeout ... ]
17:02:39 write(11, "Server 4 at 0: Entering WAITECHO\nServer 4 at 0: @Q05p 4 \'ASIA\' \'1997-01-01\'\r\nServer 4 at 1: SQL echo: @Q05p 4 \'ASIA\' \'1997-01-01\'\n"..., 4096) = 4096
17:02:39 gettimeofday({1000771359, 168640}, {420, 0}) = 0
17:02:39 gettimeofday({1000771359, 168682}, {420, 0}) = 0
17:02:39 write(1, "Kevin: ./../generic/tclTimer.c:267 Tcl_CreateTimerHander returns token 0x1fe8\n", 78) = 78
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x8077f50: exp6 armed=1\r\n", 73) = 73
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x809d8d0: exp20 armed=1\r\n", 74) = 74
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x807e088: exp8 armed=1\r\n", 73) = 73
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80930d0: exp16 armed=1\r\n", 74) = 74
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x808dcd0: exp14 armed=1\r\n", 74) = 74
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80984d0: exp18 armed=1\r\n", 74) = 74
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80834d0: exp10 armed=0\r\n", 74) = 74
17:02:39 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x80834d0, 10) called\n", 57) = 57
17:02:39 write(1, "Kevin: exp_chan.c:303 ExpWatchProc(0x80834d0, 10) calls Tcl_CreateFileHandler: 10\n", 82) = 82
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80a2cd0: exp22 armed=1\r\n", 74) = 74
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80888d0: exp12 armed=1\r\n", 74) = 74
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x8073180: exp4 armed=1\r\n", 73) = 73
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:819 Tcl_DoOneEvent() entry\n", 59) = 59
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:874 Tcl_DoOneEvent() begins ServiceEvent checks\n", 80) = 80
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:884 Tcl_DoOneEvent() ends ServiceEvent checks\n", 78) = 78
17:02:39 gettimeofday({1000771359, 169774}, {420, 0}) = 0
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:925 Tcl_DoOneEvent() calls Tcl_WaitForEvent(0x8049f10)\n", 87) = 87
17:02:39 write(1, "Kevin: ./../unix/tclUnixNotfy.c:772 select\n", 43) = 43
17:02:39 select(23, [4 6 8 10 12 14 16 18 20 22], [], [4 6 8 10 12 14 16 18 20 22], {59, 998866}) = 1 (in [10], left {60, 0})
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:331 Tcl_QueueEvent() event 0x80bbf50 \n", 70) = 70
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:422 QueueEvent 0x80bbf50 called at 0\n", 69) = 69
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:426 QueueEvent 0x80bbf50 at TAIL\n", 65) = 65
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:929 Tcl_DoOneEvent() Tcl_WaitForEvent(0x8049f10) returned 0\n", 92) = 92
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:944 Tcl_DoOneEvent() calls a checkProc\n", 71) = 71
17:02:39 write(1, "Kevin: ./../generic/tclTimer.c:406 TimerCheckProc() entry\n", 58) = 58
17:02:39 gettimeofday({1000771359, 170570}, {420, 0}) = 0
17:02:39 write(1, "Kevin: ./../generic/tclTimer.c:443 TimerCheckProc() exit\n", 57) = 57
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:948 Tcl_DoOneEvent() checkProc done\n", 68) = 68
17:02:39 write(1, "Kevin: ./../generic/tclIO.c:6512 Tcl_NotifyChannel(0x8083588,2) entered\n", 72) = 72
17:02:39 write(1, "Kevin: exp_event.c:152 exp_channelhandler called, 10, mask = 2\n", 63) = 63
17:02:39 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x80834d0, 0) called\n", 56) = 56
17:02:39 write(1, "Kevin: exp_chan.c:311 ExpWatchProc(0x80834d0, 0) calls DeleteFileHandler: 10\n", 77) = 77
17:02:39 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x80834d0, 0) called\n", 56) = 56
17:02:39 write(1, "Kevin: exp_chan.c:311 ExpWatchProc(0x80834d0, 0) calls DeleteFileHandler: 10\n", 77) = 77
17:02:39 write(1, "Kevin: ./../generic/tclIO.c:6621Tcl_NotifyChannel(0x8083588,2) done\n", 68) = 68
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:627 Tcl_ServiceEvent serviced one event\n", 72) = 72
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:959 Tcl_DoOneEvent() notices Tcl_ServiceEvent(flags)\n", 85) = 85
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:1016 Tcl_DoOneEvent() returns 1\n", 64) = 64
17:02:39 write(1, "Kevin blocking read: 10\n", 24) = 24
17:02:39 write(1, "Kevin: ./../generic/tclTimer.c:300 DeleteTimerHander called on 0x1fe8\n", 70) = 70
17:02:39 read(10, "Supplier#000007219\t\t 14\r\nSupplier#000007229\t\t 14\r\nSupplier#000008025\t\t 14\r\nSupplier#000008386\t\t 14\r\nSupplier#000008829\t\t 14\r\n"..., 4096) = 4095
17:02:39 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x80834d0, 0) called\n", 56) = 56
17:02:39 write(1, "Kevin: exp_chan.c:311 ExpWatchProc(0x80834d0, 0) calls DeleteFileHandler: 10\n", 77) = 77
17:02:39 gettimeofday({1000771359, 330039}, {420, 0}) = 0
17:02:39 gettimeofday({1000771359, 330080}, {420, 0}) = 0
17:02:39 write(1, "Kevin: ./../generic/tclTimer.c:267 Tcl_CreateTimerHander returns token 0x1fe9\n", 78) = 78
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x8077f50: exp6 armed=1\r\n", 73) = 73
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x809d8d0: exp20 armed=1\r\n", 74) = 74
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x807e088: exp8 armed=1\r\n", 73) = 73
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80930d0: exp16 armed=1\r\n", 74) = 74
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x808dcd0: exp14 armed=1\r\n", 74) = 74
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80984d0: exp18 armed=1\r\n", 74) = 74
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80834d0: exp10 armed=0\r\n", 74) = 74
17:02:39 gettimeofday({1000771359, 330679}, {420, 0}) = 0
17:02:39 gettimeofday({1000771359, 330717}, {420, 0}) = 0
17:02:39 write(1, "Kevin: ./../generic/tclTimer.c:267 Tcl_CreateTimerHander returns token 0x1fea\n", 78) = 78
17:02:39 write(1, "Kevin: ./../generic/tclIO.c:6675 UpdateInterest(0x1fea) creates handler 0x8083588 for ChannelTimerProc(0x8083588)\n", 114) = 114
17:02:39 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x80834d0, 8) called\n", 56) = 56
17:02:39 write(1, "Kevin: exp_chan.c:303 ExpWatchProc(0x80834d0, 8) calls Tcl_CreateFileHandler: 10\n", 81) = 81
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80a2cd0: exp22 armed=1\r\n", 74) = 74
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80888d0: exp12 armed=1\r\n", 74) = 74
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x8073180: exp4 armed=1\r\n", 73) = 73
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:819 Tcl_DoOneEvent() entry\n", 59) = 59
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:874 Tcl_DoOneEvent() begins ServiceEvent checks\n", 80) = 80
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:884 Tcl_DoOneEvent() ends ServiceEvent checks\n", 78) = 78
17:02:39 gettimeofday({1000771359, 331420}, {420, 0}) = 0
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:925 Tcl_DoOneEvent() calls Tcl_WaitForEvent(0x8049f10)\n", 87) = 87
17:02:39 write(1, "Kevin: ./../unix/tclUnixNotfy.c:772 select\n", 43) = 43
HERE, FD 12 IS NOTED AS HAVING DATA
17:02:39 select(23, [4 6 8 12 14 16 18 20 22], [], [4 6 8 10 12 14 16 18 20 22], {0, 0}) = 2 (in [4 12], left {0, 0})
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:331 Tcl_QueueEvent() event 0x80d75c0 \n", 70) = 70
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:422 QueueEvent 0x80d75c0 called at 0\n", 69) = 69
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:426 QueueEvent 0x80d75c0 at TAIL\n", 65) = 65
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:331 Tcl_QueueEvent() event 0x80be388 \n", 70) = 70
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:422 QueueEvent 0x80be388 called at 0\n", 69) = 69
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:426 QueueEvent 0x80be388 at TAIL\n", 65) = 65
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:929 Tcl_DoOneEvent() Tcl_WaitForEvent(0x8049f10) returned 0\n", 92) = 92
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:944 Tcl_DoOneEvent() calls a checkProc\n", 71) = 71
17:02:39 write(1, "Kevin: ./../generic/tclTimer.c:406 TimerCheckProc() entry\n", 58) = 58
17:02:39 gettimeofday({1000771359, 332393}, {420, 0}) = 0
17:02:39 write(1, "Kevin: ./../generic/tclTimer.c:436 Tcl_DriverHandlerProc() Queues entry 0x80ae718\n", 82) = 82
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:331 Tcl_QueueEvent() event 0x80ae718 \n", 70) = 70
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:422 QueueEvent 0x80ae718 called at 0\n", 69) = 69
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:426 QueueEvent 0x80ae718 at TAIL\n", 65) = 65
17:02:39 write(1, "Kevin: ./../generic/tclTimer.c:443 TimerCheckProc() exit\n", 57) = 57
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:948 Tcl_DoOneEvent() checkProc done\n", 68) = 68
17:02:39 write(1, "Kevin: ./../generic/tclIO.c:6512 Tcl_NotifyChannel(0x8088988,2) entered\n", 72) = 72
17:02:39 write(1, "Kevin: exp_event.c:152 exp_channelhandler called, 12, mask = 2\n", 63) = 63
17:02:39 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x80888d0, 0) called\n", 56) = 56
17:02:39 write(1, "Kevin: exp_chan.c:311 ExpWatchProc(0x80888d0, 0) calls DeleteFileHandler: 12\n", 77) = 77
17:02:39 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x80888d0, 0) called\n", 56) = 56
17:02:39 write(1, "Kevin: exp_chan.c:311 ExpWatchProc(0x80888d0, 0) calls DeleteFileHandler: 12\n", 77) = 77
17:02:39 write(1, "Kevin: ./../generic/tclIO.c:6621Tcl_NotifyChannel(0x8088988,2) done\n", 68) = 68
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:627 Tcl_ServiceEvent serviced one event\n", 72) = 72
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:959 Tcl_DoOneEvent() notices Tcl_ServiceEvent(flags)\n", 85) = 85
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:1016 Tcl_DoOneEvent() returns 1\n", 64) = 64
17:02:39 write(1, "Kevin blocking read: 12\n", 24) = 24
17:02:39 write(1, "Kevin: ./../generic/tclTimer.c:300 DeleteTimerHander called on 0x1fe9\n", 70) = 70
FD 12 IS READ. IT COULD HAPPEN COINCIDENTALLY THAT IT IS DRAINED (AT EXACTLY 4095 CHARS).
17:02:39 read(12, "\fS_NAME\t\t\t NUMWAIT\r\n------------------------- ----------\r\nSupplier#000007754\t\t 23\r\nSupplier#000009395\t\t 21\r\nSupplier#0000049"..., 4096) = 4095
17:02:39 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x80888d0, 0) called\n", 56) = 56
17:02:39 write(1, "Kevin: exp_chan.c:311 ExpWatchProc(0x80888d0, 0) calls DeleteFileHandler: 12\n", 77) = 77
17:02:39 write(13, "Server 5 at 0: Entering WAITECHO\nServer 5 at 0: @Q21p 5 \'MOZAMBIQUE\'\r\nServer 5 at 1: SQL echo: @Q21p 5 \'MOZAMBIQUE\'\nServer 5 at 1:"..., 4096) = 4096
17:02:39 gettimeofday({1000771359, 495573}, {420, 0}) = 0
17:02:39 write(1, "Kevin: ./../generic/tclTimer.c:267 Tcl_CreateTimerHander returns token 0x1feb\n", 78) = 78
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x8077f50: exp6 armed=1\r\n", 73) = 73
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x809d8d0: exp20 armed=1\r\n", 74) = 74
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x807e088: exp8 armed=1\r\n", 73) = 73
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80930d0: exp16 armed=1\r\n", 74) = 74
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x808dcd0: exp14 armed=1\r\n", 74) = 74
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80984d0: exp18 armed=1\r\n", 74) = 74
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80834d0: exp10 armed=1\r\n", 74) = 74
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80a2cd0: exp22 armed=1\r\n", 74) = 74
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80888d0: exp12 armed=0\r\n", 74) = 74
17:02:39 gettimeofday({1000771359, 496280}, {420, 0}) = 0
TIMER 1fec CREATED (buffers have data)
17:02:39 write(1, "Kevin: ./../generic/tclTimer.c:267 Tcl_CreateTimerHander returns token 0x1fec\n", 78) = 78
17:02:39 write(1, "Kevin: ./../generic/tclIO.c:6675 UpdateInterest(0x1fec) creates handler 0x8088988 for ChannelTimerProc(0x8088988)\n", 114) = 114
17:02:39 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x80888d0, 8) called\n", 56) = 56
17:02:39 write(1, "Kevin: exp_chan.c:303 ExpWatchProc(0x80888d0, 8) calls Tcl_CreateFileHandler: 12\n", 81) = 81
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x8073180: exp4 armed=1\r\n", 73) = 73
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:819 Tcl_DoOneEvent() entry\n", 59) = 59
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:874 Tcl_DoOneEvent() begins ServiceEvent checks\n", 80) = 80
17:02:39 write(1, "Kevin: ./../generic/tclIO.c:6512 Tcl_NotifyChannel(0x8073238,2) entered\n", 72) = 72
17:02:39 write(1, "Kevin: exp_event.c:152 exp_channelhandler called, 4, mask = 2\n", 62) = 62
17:02:39 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x8073180, 0) called\n", 56) = 56
17:02:39 write(1, "Kevin: exp_chan.c:311 ExpWatchProc(0x8073180, 0) calls DeleteFileHandler: 4\n", 76) = 76
17:02:39 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x8073180, 0) called\n", 56) = 56
17:02:39 write(1, "Kevin: exp_chan.c:311 ExpWatchProc(0x8073180, 0) calls DeleteFileHandler: 4\n", 76) = 76
17:02:39 write(1, "Kevin: ./../generic/tclIO.c:6621Tcl_NotifyChannel(0x8073238,2) done\n", 68) = 68
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:627 Tcl_ServiceEvent serviced one event\n", 72) = 72
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:878 Tcl_DoOneEvent() serviced a queued event \n", 78) = 78
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:1016 Tcl_DoOneEvent() returns 1\n", 64) = 64
17:02:39 write(1, "Kevin blocking read: 4\n", 23) = 23
17:02:39 write(1, "Kevin: ./../generic/tclTimer.c:300 DeleteTimerHander called on 0x1feb\n", 70) = 70
17:02:39 read(4, "\fS_NAME\t\t\t NUMWAIT\r\n------------------------- ----------\r\nSupplier#000004223\t\t 21\r\nSupplier#000007973\t\t 21\r\nSupplier#0000057"..., 4096) = 4095
17:02:39 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x8073180, 0) called\n", 56) = 56
17:02:39 write(1, "Kevin: exp_chan.c:311 ExpWatchProc(0x8073180, 0) calls DeleteFileHandler: 4\n", 76) = 76
17:02:39 write(5, "rmal: 0\n\nServer 1 at 1000769423: Result: kstat.complete_parsing: 0\n\nServer 1 at 1000769423: Result: kstat.nr_free_pending: 0\n\nServ"..., 4096) = 4096
17:02:39 gettimeofday({1000771359, 649422}, {420, 0}) = 0
17:02:39 write(1, "Kevin: ./../generic/tclTimer.c:267 Tcl_CreateTimerHander returns token 0x1fed\n", 78) = 78
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x8077f50: exp6 armed=1\r\n", 73) = 73
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x809d8d0: exp20 armed=1\r\n", 74) = 74
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x807e088: exp8 armed=1\r\n", 73) = 73
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80930d0: exp16 armed=1\r\n", 74) = 74
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x808dcd0: exp14 armed=1\r\n", 74) = 74
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80984d0: exp18 armed=1\r\n", 74) = 74
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80834d0: exp10 armed=1\r\n", 74) = 74
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80a2cd0: exp22 armed=1\r\n", 74) = 74
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80888d0: exp12 armed=1\r\n", 74) = 74
17:02:39 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x8073180: exp4 armed=0\r\n", 73) = 73
17:02:39 gettimeofday({1000771359, 650178}, {420, 0}) = 0
17:02:39 write(1, "Kevin: ./../generic/tclTimer.c:267 Tcl_CreateTimerHander returns token 0x1fee\n", 78) = 78
17:02:39 write(1, "Kevin: ./../generic/tclIO.c:6675 UpdateInterest(0x1fee) creates handler 0x8073238 for ChannelTimerProc(0x8073238)\n", 114) = 114
17:02:39 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x8073180, 8) called\n", 56) = 56
17:02:39 write(1, "Kevin: exp_chan.c:303 ExpWatchProc(0x8073180, 8) calls Tcl_CreateFileHandler: 4\n", 80) = 80
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:819 Tcl_DoOneEvent() entry\n", 59) = 59
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:874 Tcl_DoOneEvent() begins ServiceEvent checks\n", 80) = 80
17:02:39 gettimeofday({1000771359, 650618}, {420, 0}) = 0
17:02:39 write(1, "Kevin: ./../generic/tclIO.c:6716 ChannelTimerProc(0x8083588) handler is 0x1fea\n", 80) = 80
17:02:39 gettimeofday({1000771359, 650726}, {420, 0}) = 0
17:02:39 gettimeofday({1000771359, 650767}, {420, 0}) = 0
17:02:39 write(1, "Kevin: ./../generic/tclTimer.c:267 Tcl_CreateTimerHander returns token 0x1fef\n", 78) = 78
17:02:39 write(1, "Kevin: ./../generic/tclIO.c:6731 ChannelTimerProc(0x1fef) creates handler 0x8083588, calls notify\n", 98) = 98
17:02:39 write(1, "Kevin: ./../generic/tclIO.c:6512 Tcl_NotifyChannel(0x8083588,2) entered\n", 72) = 72
17:02:39 write(1, "Kevin: exp_event.c:152 exp_channelhandler called, 10, mask = 2\n", 63) = 63
17:02:39 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x80834d0, 0) called\n", 56) = 56
17:02:39 write(1, "Kevin: exp_chan.c:311 ExpWatchProc(0x80834d0, 0) calls DeleteFileHandler: 10\n", 77) = 77
17:02:39 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x80834d0, 0) called\n", 56) = 56
17:02:39 write(1, "Kevin: exp_chan.c:311 ExpWatchProc(0x80834d0, 0) calls DeleteFileHandler: 10\n", 77) = 77
17:02:39 write(1, "Kevin: ./../generic/tclIO.c:6621Tcl_NotifyChannel(0x8083588,2) done\n", 68) = 68
17:02:39 write(1, "Kevin: ./../generic/tclIO.c:6716 ChannelTimerProc(0x8088988) handler is 0x1fec\n", 80) = 80
17:02:39 gettimeofday({1000771359, 651480}, {420, 0}) = 0
17:02:39 gettimeofday({1000771359, 651521}, {420, 0}) = 0
TIMER 1fec SPAWNS 1ff0, CAUSES NOTIFY
17:02:39 write(1, "Kevin: ./../generic/tclTimer.c:267 Tcl_CreateTimerHander returns token 0x1ff0\n", 78) = 78
17:02:39 write(1, "Kevin: ./../generic/tclIO.c:6731 ChannelTimerProc(0x1ff0) creates handler 0x8088988, calls notify\n", 98) = 98
17:02:39 write(1, "Kevin: ./../generic/tclIO.c:6512 Tcl_NotifyChannel(0x8088988,2) entered\n", 72) = 72
17:02:39 write(1, "Kevin: exp_event.c:152 exp_channelhandler called, 12, mask = 2\n", 63) = 63
17:02:39 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x80888d0, 0) called\n", 56) = 56
17:02:39 write(1, "Kevin: exp_chan.c:311 ExpWatchProc(0x80888d0, 0) calls DeleteFileHandler: 12\n", 77) = 77
17:02:39 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x80888d0, 0) called\n", 56) = 56
17:02:39 write(1, "Kevin: exp_chan.c:311 ExpWatchProc(0x80888d0, 0) calls DeleteFileHandler: 12\n", 77) = 77
17:02:39 write(1, "Kevin: ./../generic/tclIO.c:6621Tcl_NotifyChannel(0x8088988,2) done\n", 68) = 68
17:02:39 write(1, "Kevin: ./../generic/tclIO.c:6716 ChannelTimerProc(0x8073238) handler is 0x1fee\n", 80) = 80
17:02:39 gettimeofday({1000771359, 652207}, {420, 0}) = 0
17:02:39 gettimeofday({1000771359, 652248}, {420, 0}) = 0
17:02:39 write(1, "Kevin: ./../generic/tclTimer.c:267 Tcl_CreateTimerHander returns token 0x1ff1\n", 78) = 78
17:02:39 write(1, "Kevin: ./../generic/tclIO.c:6731 ChannelTimerProc(0x1ff1) creates handler 0x8073238, calls notify\n", 98) = 98
17:02:39 write(1, "Kevin: ./../generic/tclIO.c:6512 Tcl_NotifyChannel(0x8073238,2) entered\n", 72) = 72
17:02:39 write(1, "Kevin: exp_event.c:152 exp_channelhandler called, 4, mask = 2\n", 62) = 62
17:02:39 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x8073180, 0) called\n", 56) = 56
17:02:39 write(1, "Kevin: exp_chan.c:311 ExpWatchProc(0x8073180, 0) calls DeleteFileHandler: 4\n", 76) = 76
17:02:39 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x8073180, 0) called\n", 56) = 56
17:02:39 write(1, "Kevin: exp_chan.c:311 ExpWatchProc(0x8073180, 0) calls DeleteFileHandler: 4\n", 76) = 76
17:02:39 write(1, "Kevin: ./../generic/tclIO.c:6621Tcl_NotifyChannel(0x8073238,2) done\n", 68) = 68
17:02:39 gettimeofday({1000771359, 652883}, {420, 0}) = 0
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:627 Tcl_ServiceEvent serviced one event\n", 72) = 72
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:878 Tcl_DoOneEvent() serviced a queued event \n", 78) = 78
17:02:39 write(1, "Kevin: ./../generic/tclNotify.c:1016 Tcl_DoOneEvent() returns 1\n", 64) = 64
17:02:39 write(1, "Kevin blocking read: 10\n", 24) = 24
17:02:39 write(1, "Kevin: ./../generic/tclTimer.c:300 DeleteTimerHander called on 0x1fed\n", 70) = 70
17:02:39 read(10, "08064\t\t 10\r\nSupplier#000008204\t\t 10\r\nSupplier#000008628\t\t 10\r\nSupplier#000008779\t\t 10\r\nSupplier#000009131\t\t 10\r\nSupplier#0000"..., 4096) = 4095
17:02:39 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x80834d0, 0) called\n", 56) = 56
17:02:39 write(1, "Kevin: exp_chan.c:311 ExpWatchProc(0x80834d0, 0) calls DeleteFileHandler: 10\n", 77) = 77
FD 12 IS READ AGAIN, BUT NO select() CALL HAS ASSURED US THIS IS OKAY. WE GET AWAY WITH IT THIS TIME.
BUT AGAIN, THIS WOULD BE A GOOD TIME TO KILL OFF THE TIMER IF THE BUFFERS ARE EMPTY.
THIS MESSAGE COMES FROM exp_event.c, SORRY I MISSED THAT ONE. BUT THE READ IS INSIDE TCL.
17:02:39 write(1, "Kevin blocking read: 12\n", 24) = 24
17:02:39 read(12, "plier#000009026\t\t 11\r\nSupplier#000009173\t\t 11\r\nSupplier#000009204\t\t 11\r\nSupplier#000009371\t\t 11\r\nSupplier#000009481\t\t 11\r\nSup"..., 4096) = 4095
17:02:39 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x80888d0, 0) called\n", 56) = 56
17:02:39 write(1, "Kevin: exp_chan.c:311 ExpWatchProc(0x80888d0, 0) calls DeleteFileHandler: 12\n", 77) = 77
17:02:40 write(1, "Kevin blocking read: 4\n", 23) = 23
17:02:40 read(4, "plier#000006355\t\t 11\r\nSupplier#000006524\t\t 11\r\nSupplier#000006829\t\t 11\r\nSupplier#000006994\t\t 11\r\nSupplier#000007191\t\t 11\r\nSup"..., 4096) = 4095
17:02:40 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x8073180, 0) called\n", 56) = 56
17:02:40 write(1, "Kevin: exp_chan.c:311 ExpWatchProc(0x8073180, 0) calls DeleteFileHandler: 4\n", 76) = 76
17:02:40 gettimeofday({1000771360, 168081}, {420, 0}) = 0
17:02:40 gettimeofday({1000771360, 168122}, {420, 0}) = 0
17:02:40 write(1, "Kevin: ./../generic/tclTimer.c:267 Tcl_CreateTimerHander returns token 0x1ff2\n", 78) = 78
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x8077f50: exp6 armed=1\r\n", 73) = 73
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x809d8d0: exp20 armed=1\r\n", 74) = 74
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x807e088: exp8 armed=1\r\n", 73) = 73
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80930d0: exp16 armed=1\r\n", 74) = 74
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x808dcd0: exp14 armed=1\r\n", 74) = 74
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80984d0: exp18 armed=1\r\n", 74) = 74
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80834d0: exp10 armed=0\r\n", 74) = 74
17:02:40 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x80834d0, 8) called\n", 56) = 56
17:02:40 write(1, "Kevin: exp_chan.c:303 ExpWatchProc(0x80834d0, 8) calls Tcl_CreateFileHandler: 10\n", 81) = 81
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80a2cd0: exp22 armed=1\r\n", 74) = 74
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80888d0: exp12 armed=0\r\n", 74) = 74
17:02:40 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x80888d0, 8) called\n", 56) = 56
17:02:40 write(1, "Kevin: exp_chan.c:303 ExpWatchProc(0x80888d0, 8) calls Tcl_CreateFileHandler: 12\n", 81) = 81
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x8073180: exp4 armed=0\r\n", 73) = 73
17:02:40 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x8073180, 8) called\n", 56) = 56
17:02:40 write(1, "Kevin: exp_chan.c:303 ExpWatchProc(0x8073180, 8) calls Tcl_CreateFileHandler: 4\n", 80) = 80
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:819 Tcl_DoOneEvent() entry\n", 59) = 59
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:874 Tcl_DoOneEvent() begins ServiceEvent checks\n", 80) = 80
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:884 Tcl_DoOneEvent() ends ServiceEvent checks\n", 78) = 78
17:02:40 gettimeofday({1000771360, 170694}, {420, 0}) = 0
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:925 Tcl_DoOneEvent() calls Tcl_WaitForEvent(0x8049f10)\n", 87) = 87
17:02:40 write(1, "Kevin: ./../unix/tclUnixNotfy.c:772 select\n", 43) = 43
NOT EVEN TRYING TO TEST CHANNEL 12
17:02:40 select(23, [6 8 14 16 18 20 22], [], [4 6 8 10 12 14 16 18 20 22], {0, 0}) = 0 (Timeout)
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:929 Tcl_DoOneEvent() Tcl_WaitForEvent(0x8049f10) returned 0\n", 92) = 92
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:944 Tcl_DoOneEvent() calls a checkProc\n", 71) = 71
17:02:40 write(1, "Kevin: ./../generic/tclTimer.c:406 TimerCheckProc() entry\n", 58) = 58
17:02:40 gettimeofday({1000771360, 171262}, {420, 0}) = 0
17:02:40 write(1, "Kevin: ./../generic/tclTimer.c:436 Tcl_DriverHandlerProc() Queues entry 0x8077b28\n", 82) = 82
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:331 Tcl_QueueEvent() event 0x8077b28 \n", 70) = 70
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:422 QueueEvent 0x8077b28 called at 0\n", 69) = 69
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:426 QueueEvent 0x8077b28 at TAIL\n", 65) = 65
17:02:40 write(1, "Kevin: ./../generic/tclTimer.c:443 TimerCheckProc() exit\n", 57) = 57
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:948 Tcl_DoOneEvent() checkProc done\n", 68) = 68
17:02:40 gettimeofday({1000771360, 171675}, {420, 0}) = 0
17:02:40 write(1, "Kevin: ./../generic/tclIO.c:6716 ChannelTimerProc(0x8083588) handler is 0x1fef\n", 80) = 80
17:02:40 gettimeofday({1000771360, 171782}, {420, 0}) = 0
17:02:40 gettimeofday({1000771360, 171821}, {420, 0}) = 0
17:02:40 write(1, "Kevin: ./../generic/tclTimer.c:267 Tcl_CreateTimerHander returns token 0x1ff3\n", 78) = 78
17:02:40 write(1, "Kevin: ./../generic/tclIO.c:6731 ChannelTimerProc(0x1ff3) creates handler 0x8083588, calls notify\n", 98) = 98
17:02:40 write(1, "Kevin: ./../generic/tclIO.c:6512 Tcl_NotifyChannel(0x8083588,2) entered\n", 72) = 72
17:02:40 write(1, "Kevin: exp_event.c:152 exp_channelhandler called, 10, mask = 2\n", 63) = 63
17:02:40 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x80834d0, 0) called\n", 56) = 56
17:02:40 write(1, "Kevin: exp_chan.c:311 ExpWatchProc(0x80834d0, 0) calls DeleteFileHandler: 10\n", 77) = 77
17:02:40 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x80834d0, 0) called\n", 56) = 56
17:02:40 write(1, "Kevin: exp_chan.c:311 ExpWatchProc(0x80834d0, 0) calls DeleteFileHandler: 10\n", 77) = 77
17:02:40 write(1, "Kevin: ./../generic/tclIO.c:6621Tcl_NotifyChannel(0x8083588,2) done\n", 68) = 68
17:02:40 write(1, "Kevin: ./../generic/tclIO.c:6716 ChannelTimerProc(0x8088988) handler is 0x1ff0\n", 80) = 80
17:02:40 gettimeofday({1000771360, 172512}, {420, 0}) = 0
17:02:40 gettimeofday({1000771360, 172551}, {420, 0}) = 0
TIMER 1ff0 SPAWNS 1ff4
17:02:40 write(1, "Kevin: ./../generic/tclTimer.c:267 Tcl_CreateTimerHander returns token 0x1ff4\n", 78) = 78
17:02:40 write(1, "Kevin: ./../generic/tclIO.c:6731 ChannelTimerProc(0x1ff4) creates handler 0x8088988, calls notify\n", 98) = 98
FD 12 NOTIFIED BY TIMER 1ff0.
17:02:40 write(1, "Kevin: ./../generic/tclIO.c:6512 Tcl_NotifyChannel(0x8088988,2) entered\n", 72) = 72
17:02:40 write(1, "Kevin: exp_event.c:152 exp_channelhandler called, 12, mask = 2\n", 63) = 63
17:02:40 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x80888d0, 0) called\n", 56) = 56
17:02:40 write(1, "Kevin: exp_chan.c:311 ExpWatchProc(0x80888d0, 0) calls DeleteFileHandler: 12\n", 77) = 77
17:02:40 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x80888d0, 0) called\n", 56) = 56
17:02:40 write(1, "Kevin: exp_chan.c:311 ExpWatchProc(0x80888d0, 0) calls DeleteFileHandler: 12\n", 77) = 77
17:02:40 write(1, "Kevin: ./../generic/tclIO.c:6621Tcl_NotifyChannel(0x8088988,2) done\n", 68) = 68
17:02:40 write(1, "Kevin: ./../generic/tclIO.c:6716 ChannelTimerProc(0x8073238) handler is 0x1ff1\n", 80) = 80
17:02:40 gettimeofday({1000771360, 173298}, {420, 0}) = 0
17:02:40 gettimeofday({1000771360, 173338}, {420, 0}) = 0
17:02:40 write(1, "Kevin: ./../generic/tclTimer.c:267 Tcl_CreateTimerHander returns token 0x1ff5\n", 78) = 78
17:02:40 write(1, "Kevin: ./../generic/tclIO.c:6731 ChannelTimerProc(0x1ff5) creates handler 0x8073238, calls notify\n", 98) = 98
17:02:40 write(1, "Kevin: ./../generic/tclIO.c:6512 Tcl_NotifyChannel(0x8073238,2) entered\n", 72) = 72
17:02:40 write(1, "Kevin: exp_event.c:152 exp_channelhandler called, 4, mask = 2\n", 62) = 62
17:02:40 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x8073180, 0) called\n", 56) = 56
17:02:40 write(1, "Kevin: exp_chan.c:311 ExpWatchProc(0x8073180, 0) calls DeleteFileHandler: 4\n", 76) = 76
17:02:40 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x8073180, 0) called\n", 56) = 56
17:02:40 write(1, "Kevin: exp_chan.c:311 ExpWatchProc(0x8073180, 0) calls DeleteFileHandler: 4\n", 76) = 76
17:02:40 write(1, "Kevin: ./../generic/tclIO.c:6621Tcl_NotifyChannel(0x8073238,2) done\n", 68) = 68
17:02:40 gettimeofday({1000771360, 173941}, {420, 0}) = 0
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:627 Tcl_ServiceEvent serviced one event\n", 72) = 72
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:959 Tcl_DoOneEvent() notices Tcl_ServiceEvent(flags)\n", 85) = 85
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:1016 Tcl_DoOneEvent() returns 1\n", 64) = 64
17:02:40 write(1, "Kevin blocking read: 10\n", 24) = 24
17:02:40 write(1, "Kevin: ./../generic/tclTimer.c:300 DeleteTimerHander called on 0x1ff2\n", 70) = 70
17:02:40 read(10, "Supplier#000001755\t\t 6\r\nSupplier#000002655\t\t 6\r\nSupplier#000002888\t\t 6\r\nSupplier#000003011\t\t 6\r\nSupplier#000003038\t\t 6\r\n"..., 4096) = 2768
17:02:40 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x80834d0, 0) called\n", 56) = 56
17:02:40 write(1, "Kevin: exp_chan.c:311 ExpWatchProc(0x80834d0, 0) calls DeleteFileHandler: 10\n", 77) = 77
17:02:40 write(1, "Server 4 stream 4 query 21: start 139, end 1937 Elapsed time: 1798 seconds\n", 75) = 75
17:02:40 write(11, "rver 4 at 1936: Supplier#000005289\t\t 15\nServer 4 at 1936: Supplier#000005308\t\t 15\nServer 4 at 1936: Supplier#000006226\t\t 15\nSer"..., 4096) = 4096
17:02:40 write(1, "Server 4 stream 4 query 21: 1071350 consistent gets\n", 57) = 57
17:02:40 write(1, "Server 4 stream 4 query 21: 20832 physical reads\n", 56) = 56
17:02:40 write(1, "Server 4 stream 4 trailer done at 1937\n", 39) = 39
17:02:40 write(10, "@Q14p 4 \'1996-12-01\'\r", 21) = 21
17:02:40 write(1, "Server 4 id exp10 stream 4 qtime 0 query 14 at 1937: @Q14p 4 \'1996-12-01\'\r\n", 75) = 75
17:02:40 write(1, "Running the main \'expect\' command.\n", 35) = 35
17:02:40 write(1, "Kevin blocking read: 4\n", 23) = 23
17:02:40 read(4, "60\t\t 8\r\nSupplier#000008985\t\t 8\r\nSupplier#000009195\t\t 8\r\nSupplier#000009490\t\t 8\r\nSupplier#000009588\t\t 8\r\nSupplier#0000098"..., 4096) = 3766
17:02:40 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x8073180, 0) called\n", 56) = 56
17:02:40 write(1, "Kevin: exp_chan.c:311 ExpWatchProc(0x8073180, 0) calls DeleteFileHandler: 4\n", 76) = 76
17:02:40 write(1, "Server 1 stream 1 query 21: start 0, end 1937 Elapsed time: 1937 seconds\n", 73) = 73
17:02:40 write(1, "Server 1 stream 1 query 21: 1067327 consistent gets\n", 57) = 57
17:02:40 write(5, "r 1 at 1936: Supplier#000009516\t\t 14\nServer 1 at 1936: Supplier#000009541\t\t 14\nServer 1 at 1936: Supplier#000009704\t\t 14\nServer"..., 4096) = 4096
17:02:40 write(1, "Server 1 stream 1 query 21: 20997 physical reads\n", 56) = 56
17:02:40 write(1, "Server 1 stream 1 trailer done at 1937\n", 39) = 39
17:02:40 write(4, "@Q03p 1 \'AUTOMOBILE\' \'1995-03-12\'\r", 34) = 34
17:02:40 write(1, "Server 1 id exp4 stream 1 qtime 0 query 3 at 1937: @Q03p 1 \'AUTOMOBILE\' \'1995-03-12\'\r\n", 86) = 86
17:02:40 write(1, "Running the main \'expect\' command.\n", 35) = 35
17:02:40 write(1, "Kevin blocking read: 12\n", 24) = 24
ONCE AGAIN FD 12 IS READ. ONCE AGAIN WE GET AWAY WITH IT. HOWEVER, THIS READ RETURNS A SHORT BUFFER,
WHICH COULD WARN US OF TROUBLE AHEAD. (BUT THE SAME THING COULD BE TRUE WITH A FULL BUFFER, SOMETIMES)
17:02:40 read(12, "99\t\t 8\r\nSupplier#000009886\t\t 8\r\nSupplier#000000058\t\t 7\r\nSupplier#000000093\t\t 7\r\nSupplier#000000178\t\t 7\r\nSupplier#0000003"..., 4096) = 3974
17:02:40 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x80888d0, 0) called\n", 56) = 56
17:02:40 write(1, "Kevin: exp_chan.c:311 ExpWatchProc(0x80888d0, 0) calls DeleteFileHandler: 12\n", 77) = 77
17:02:40 write(1, "Server 5 stream 5 query 21: start 0, end 1937 Elapsed time: 1937 seconds\n", 73) = 73
17:02:40 write(1, "Server 5 stream 5 query 21: 1092163 consistent gets\n", 57) = 57
17:02:40 write(1, "Server 5 stream 5 query 21: 19004 physical reads\n", 56) = 56
17:02:40 gettimeofday({1000771360, 623271}, {420, 0}) = 0
17:02:40 gettimeofday({1000771360, 623312}, {420, 0}) = 0
17:02:40 write(1, "Kevin: ./../generic/tclTimer.c:267 Tcl_CreateTimerHander returns token 0x1ff6\n", 78) = 78
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x8073180: exp4 armed=0\r\n", 73) = 73
17:02:40 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x8073180, 10) called\n", 57) = 57
17:02:40 write(1, "Kevin: exp_chan.c:303 ExpWatchProc(0x8073180, 10) calls Tcl_CreateFileHandler: 4\n", 81) = 81
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80834d0: exp10 armed=0\r\n", 74) = 74
17:02:40 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x80834d0, 10) called\n", 57) = 57
17:02:40 write(1, "Kevin: exp_chan.c:303 ExpWatchProc(0x80834d0, 10) calls Tcl_CreateFileHandler: 10\n", 82) = 82
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80888d0: exp12 armed=0\r\n", 74) = 74
17:02:40 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x80888d0, 8) called\n", 56) = 56
17:02:40 write(1, "Kevin: exp_chan.c:303 ExpWatchProc(0x80888d0, 8) calls Tcl_CreateFileHandler: 12\n", 81) = 81
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x8077f50: exp6 armed=1\r\n", 73) = 73
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x809d8d0: exp20 armed=1\r\n", 74) = 74
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x807e088: exp8 armed=1\r\n", 73) = 73
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80930d0: exp16 armed=1\r\n", 74) = 74
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x808dcd0: exp14 armed=1\r\n", 74) = 74
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80984d0: exp18 armed=1\r\n", 74) = 74
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80a2cd0: exp22 armed=1\r\n", 74) = 74
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:819 Tcl_DoOneEvent() entry\n", 59) = 59
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:874 Tcl_DoOneEvent() begins ServiceEvent checks\n", 80) = 80
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:884 Tcl_DoOneEvent() ends ServiceEvent checks\n", 78) = 78
17:02:40 gettimeofday({1000771360, 624659}, {420, 0}) = 0
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:925 Tcl_DoOneEvent() calls Tcl_WaitForEvent(0x8049f10)\n", 87) = 87
17:02:40 write(1, "Kevin: ./../unix/tclUnixNotfy.c:772 select\n", 43) = 43
STILL NOT EVEN TESTING FD 12.
17:02:40 select(23, [4 6 8 10 14 16 18 20 22], [], [4 6 8 10 12 14 16 18 20 22], {0, 0}) = 2 (in [4 10], left {0, 0})
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:331 Tcl_QueueEvent() event 0x80be528 \n", 70) = 70
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:422 QueueEvent 0x80be528 called at 0\n", 69) = 69
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:426 QueueEvent 0x80be528 at TAIL\n", 65) = 65
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:331 Tcl_QueueEvent() event 0x80d75c0 \n", 70) = 70
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:422 QueueEvent 0x80d75c0 called at 0\n", 69) = 69
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:426 QueueEvent 0x80d75c0 at TAIL\n", 65) = 65
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:929 Tcl_DoOneEvent() Tcl_WaitForEvent(0x8049f10) returned 0\n", 92) = 92
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:944 Tcl_DoOneEvent() calls a checkProc\n", 71) = 71
17:02:40 write(1, "Kevin: ./../generic/tclTimer.c:406 TimerCheckProc() entry\n", 58) = 58
17:02:40 gettimeofday({1000771360, 625645}, {420, 0}) = 0
17:02:40 write(1, "Kevin: ./../generic/tclTimer.c:436 Tcl_DriverHandlerProc() Queues entry 0x80c8e50\n", 82) = 82
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:331 Tcl_QueueEvent() event 0x80c8e50 \n", 70) = 70
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:422 QueueEvent 0x80c8e50 called at 0\n", 69) = 69
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:426 QueueEvent 0x80c8e50 at TAIL\n", 65) = 65
17:02:40 write(1, "Kevin: ./../generic/tclTimer.c:443 TimerCheckProc() exit\n", 57) = 57
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:948 Tcl_DoOneEvent() checkProc done\n", 68) = 68
17:02:40 write(1, "Kevin: ./../generic/tclIO.c:6512 Tcl_NotifyChannel(0x8083588,2) entered\n", 72) = 72
17:02:40 write(1, "Kevin: exp_event.c:152 exp_channelhandler called, 10, mask = 2\n", 63) = 63
17:02:40 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x80834d0, 0) called\n", 56) = 56
17:02:40 write(1, "Kevin: exp_chan.c:311 ExpWatchProc(0x80834d0, 0) calls DeleteFileHandler: 10\n", 77) = 77
17:02:40 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x80834d0, 0) called\n", 56) = 56
17:02:40 write(1, "Kevin: exp_chan.c:311 ExpWatchProc(0x80834d0, 0) calls DeleteFileHandler: 10\n", 77) = 77
17:02:40 write(1, "Kevin: ./../generic/tclIO.c:6621Tcl_NotifyChannel(0x8083588,2) done\n", 68) = 68
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:627 Tcl_ServiceEvent serviced one event\n", 72) = 72
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:959 Tcl_DoOneEvent() notices Tcl_ServiceEvent(flags)\n", 85) = 85
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:1016 Tcl_DoOneEvent() returns 1\n", 64) = 64
17:02:40 write(1, "Kevin blocking read: 10\n", 24) = 24
17:02:40 write(1, "Kevin: ./../generic/tclTimer.c:300 DeleteTimerHander called on 0x1ff6\n", 70) = 70
17:02:40 read(10, "@Q14p 4 \'1996-12-01\'\r\n", 4096) = 22
17:02:40 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x80834d0, 0) called\n", 56) = 56
17:02:40 write(1, "Kevin: exp_chan.c:311 ExpWatchProc(0x80834d0, 0) calls DeleteFileHandler: 10\n", 77) = 77
17:02:40 gettimeofday({1000771360, 628210}, {420, 0}) = 0
17:02:40 write(1, "Kevin: ./../generic/tclTimer.c:267 Tcl_CreateTimerHander returns token 0x1ff7\n", 78) = 78
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x8073180: exp4 armed=1\r\n", 73) = 73
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80834d0: exp10 armed=0\r\n", 74) = 74
17:02:40 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x80834d0, 10) called\n", 57) = 57
17:02:40 write(1, "Kevin: exp_chan.c:303 ExpWatchProc(0x80834d0, 10) calls Tcl_CreateFileHandler: 10\n", 82) = 82
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80888d0: exp12 armed=1\r\n", 74) = 74
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x8077f50: exp6 armed=1\r\n", 73) = 73
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x809d8d0: exp20 armed=1\r\n", 74) = 74
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x807e088: exp8 armed=1\r\n", 73) = 73
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80930d0: exp16 armed=1\r\n", 74) = 74
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x808dcd0: exp14 armed=1\r\n", 74) = 74
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80984d0: exp18 armed=1\r\n", 74) = 74
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80a2cd0: exp22 armed=1\r\n", 74) = 74
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:819 Tcl_DoOneEvent() entry\n", 59) = 59
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:874 Tcl_DoOneEvent() begins ServiceEvent checks\n", 80) = 80
17:02:40 write(1, "Kevin: ./../generic/tclIO.c:6512 Tcl_NotifyChannel(0x8073238,2) entered\n", 72) = 72
17:02:40 write(1, "Kevin: exp_event.c:152 exp_channelhandler called, 4, mask = 2\n", 62) = 62
17:02:40 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x8073180, 0) called\n", 56) = 56
17:02:40 write(1, "Kevin: exp_chan.c:311 ExpWatchProc(0x8073180, 0) calls DeleteFileHandler: 4\n", 76) = 76
17:02:40 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x8073180, 0) called\n", 56) = 56
17:02:40 write(1, "Kevin: exp_chan.c:311 ExpWatchProc(0x8073180, 0) calls DeleteFileHandler: 4\n", 76) = 76
17:02:40 write(1, "Kevin: ./../generic/tclIO.c:6621Tcl_NotifyChannel(0x8073238,2) done\n", 68) = 68
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:627 Tcl_ServiceEvent serviced one event\n", 72) = 72
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:878 Tcl_DoOneEvent() serviced a queued event \n", 78) = 78
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:1016 Tcl_DoOneEvent() returns 1\n", 64) = 64
17:02:40 write(1, "Kevin blocking read: 4\n", 23) = 23
17:02:40 write(1, "Kevin: ./../generic/tclTimer.c:300 DeleteTimerHander called on 0x1ff7\n", 70) = 70
17:02:40 read(4, "@Q03p 1 \'AUTOMOBILE\' \'1995-03-12\'\r\n", 4096) = 35
17:02:40 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x8073180, 0) called\n", 56) = 56
17:02:40 write(1, "Kevin: exp_chan.c:311 ExpWatchProc(0x8073180, 0) calls DeleteFileHandler: 4\n", 76) = 76
17:02:40 gettimeofday({1000771360, 631358}, {420, 0}) = 0
17:02:40 write(1, "Kevin: ./../generic/tclTimer.c:267 Tcl_CreateTimerHander returns token 0x1ff8\n", 78) = 78
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x8073180: exp4 armed=0\r\n", 73) = 73
17:02:40 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x8073180, 10) called\n", 57) = 57
17:02:40 write(1, "Kevin: exp_chan.c:303 ExpWatchProc(0x8073180, 10) calls Tcl_CreateFileHandler: 4\n", 81) = 81
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80834d0: exp10 armed=1\r\n", 74) = 74
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80888d0: exp12 armed=1\r\n", 74) = 74
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x8077f50: exp6 armed=1\r\n", 73) = 73
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x809d8d0: exp20 armed=1\r\n", 74) = 74
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x807e088: exp8 armed=1\r\n", 73) = 73
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80930d0: exp16 armed=1\r\n", 74) = 74
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x808dcd0: exp14 armed=1\r\n", 74) = 74
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80984d0: exp18 armed=1\r\n", 74) = 74
17:02:40 write(1, "Kevin: exp_event.c:268 Tcl_CreateChannelHandler 0x80a2cd0: exp22 armed=1\r\n", 74) = 74
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:819 Tcl_DoOneEvent() entry\n", 59) = 59
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:874 Tcl_DoOneEvent() begins ServiceEvent checks\n", 80) = 80
17:02:40 gettimeofday({1000771360, 632384}, {420, 0}) = 0
17:02:40 write(1, "Kevin: ./../generic/tclIO.c:6716 ChannelTimerProc(0x8083588) handler is 0x1ff3\n", 80) = 80
17:02:40 write(1, "Kevin: ./../generic/tclIO.c:6737 ChannelTimerProc(0x8083588) clears off (no action)\n", 84) = 84
17:02:40 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x80834d0, 10) called\n", 57) = 57
17:02:40 write(1, "Kevin: exp_chan.c:303 ExpWatchProc(0x80834d0, 10) calls Tcl_CreateFileHandler: 10\n", 82) = 82
17:02:40 write(1, "Kevin: ./../generic/tclIO.c:6716 ChannelTimerProc(0x8088988) handler is 0x1ff4\n", 80) = 80
17:02:40 gettimeofday({1000771360, 632746}, {420, 0}) = 0
17:02:40 gettimeofday({1000771360, 632784}, {420, 0}) = 0
TIMER 1ff4 SPAWNS 1ff9
17:02:40 write(1, "Kevin: ./../generic/tclTimer.c:267 Tcl_CreateTimerHander returns token 0x1ff9\n", 78) = 78
17:02:40 write(1, "Kevin: ./../generic/tclIO.c:6731 ChannelTimerProc(0x1ff9) creates handler 0x8088988, calls notify\n", 98) = 98
CHANNEL NOTIFIED
17:02:40 write(1, "Kevin: ./../generic/tclIO.c:6512 Tcl_NotifyChannel(0x8088988,2) entered\n", 72) = 72
17:02:40 write(1, "Kevin: exp_event.c:152 exp_channelhandler called, 12, mask = 2\n", 63) = 63
17:02:40 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x80888d0, 0) called\n", 56) = 56
17:02:40 write(1, "Kevin: exp_chan.c:311 ExpWatchProc(0x80888d0, 0) calls DeleteFileHandler: 12\n", 77) = 77
17:02:40 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x80888d0, 0) called\n", 56) = 56
17:02:40 write(1, "Kevin: exp_chan.c:311 ExpWatchProc(0x80888d0, 0) calls DeleteFileHandler: 12\n", 77) = 77
17:02:40 write(1, "Kevin: ./../generic/tclIO.c:6621Tcl_NotifyChannel(0x8088988,2) done\n", 68) = 68
17:02:40 write(1, "Kevin: ./../generic/tclIO.c:6716 ChannelTimerProc(0x8073238) handler is 0x1ff5\n", 80) = 80
17:02:40 write(1, "Kevin: ./../generic/tclIO.c:6737 ChannelTimerProc(0x8073238) clears off (no action)\n", 84) = 84
17:02:40 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x8073180, 10) called\n", 57) = 57
17:02:40 write(1, "Kevin: exp_chan.c:303 ExpWatchProc(0x8073180, 10) calls Tcl_CreateFileHandler: 4\n", 81) = 81
17:02:40 gettimeofday({1000771360, 633647}, {420, 0}) = 0
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:627 Tcl_ServiceEvent serviced one event\n", 72) = 72
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:878 Tcl_DoOneEvent() serviced a queued event \n", 78) = 78
17:02:40 write(1, "Kevin: ./../generic/tclNotify.c:1016 Tcl_DoOneEvent() returns 1\n", 64) = 64
17:02:40 write(1, "Kevin blocking read: 12\n", 24) = 24
17:02:40 write(1, "Kevin: ./../generic/tclTimer.c:300 DeleteTimerHander called on 0x1ff8\n", 70) = 70
ONCE AGAIN FD 12 IS READ. WE'RE NOT SO LUCKY THIS TIME.
17:02:40 read(12, 0x808dfc8, 4096) = ? ERESTARTSYS (To be restarted)
WEDGED READ
01:26:14 --- SIGCHLD (Child exited) ---
01:26:14 read(12, 0x808dfc8, 4096) = -1 EIO (Input/output error)
01:26:14 write(1, "Kevin: exp_chan.c:292 ExpWatchProc(0x80888d0, 0) called\n", 56) = 56
01:26:14 write(1, "Kevin: exp_chan.c:311 ExpWatchProc(0x80888d0, 0) calls DeleteFileHandler: 12\n", 77) = 77
01:26:14 close(12) = 0
[snippage]
