Bug 372692 - [TCF][Agent] TCF agent generated truncated process stdout streams.
Summary: [TCF][Agent] TCF agent generated truncated process stdout streams.
Status: RESOLVED FIXED
Alias: None
Product: TCF
Classification: Tools
Component: Agent (show other bugs)
Version: unspecified   Edit
Hardware: PC Windows XP
: P3 major (vote)
Target Milestone: 1.0.0   Edit
Assignee: Project Inbox CLA
QA Contact: Eugene Tarassov CLA
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2012-02-27 22:08 EST by William Chen CLA
Modified: 2013-06-05 05:42 EDT (History)
2 users (show)

See Also:

Attachments
Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.
Description William Chen CLA 2012-02-27 22:08:46 EST 
When using [Target Explorer view]->[Run Remote Process...] to run command "ls -l" on a linux TCF agent, the output in the console looks like below:

total 6780
-rwxr-xr-x 1 root root  818232 2010-04-19 09:51 bash
-rwxr-xr-x 3 root root   30200 2011-12-13 06:40 bunzip2
-rwxr-xr-x 1 root root 1269432 2010-04-23 04:04 busybox
-rwxr-xr-x 3 root root   30200 2011-12-13 06:40 bzcat
lrwxrwxrwx 1 root root       6 2011-12-21 11:09 bzcmp -> bzdiff
-rwxr-xr-x 1 root root    2140 2011-12-13 06:40 bzdiff
lrwxrwxrwx 1 root root       6 2011-12-21 11:09 bzegrep -> bzgrep
-rwxr-xr-x 1 root root    4877 2011-12-13 06:40 bzexe
lrwxrwxrwx 1 root root       6 2011-12-21 11:09 bzfgrep -> bzgrep
-rwxr-xr-x 1 root root    3642 2011-12-13 06:40 bzgrep
-rwxr-xr-x 3 root root   30200 2011-12-13 06:40 bzip2
-rwxr-xr-x 1 root root    9580 2011-12-13 06:40 bzip2recover
lrwxrwxrwx 1 root root       6 2011-12-21 11:09 bzless -> bzmore
-rwxr-xr-x 1 root root    1297 2011-12-13 06:40 bzmore
-rwxr-xr-x 1 root root   50820 2010-09-22 02:33 cat
-rwxr-xr-x 1 root root   54956 2010-09-22 02:33 chgrp
-rwxr-xr-x 1 root root   50836 2010-09-22 02:33 chmod
-rwxr-xr-x 1 root root   54964 2010-09-22 02:33 chown
-rwxr-xr-x 1 root root    9632 2010-03-12 15:05 chvt
-rwxr-xr-x 1 root root   96140 2010-09-22 02:33 cp
-rwxr-xr-x 1 root root  114448 2010-03-05 11:25 cpio
-rwxr-xr-x 1 root root   83888 2010-04-02 03:22 dash
-rwxr-xr-x 1 root root   63128 2010-09-22 02:33 date
-rwxr-xr-x 1 root root    9672 2011-07-23 01:02 dbus-cleanup-sockets
-rwxr-xr-x 1 root root  292728 2011-07-23 01:02 dbus-daemon
-rwxr-xr-x 1 root root    5524 2011-07-23 01:02 dbus-uuidgen
-rwxr-xr-x 1 root root   54996 2010-09-22 02:33 dd
-rwxr-xr-x 1 root root   67316 2010-09-22 02:33 df
-rwxr-xr-x 1 root root  104528 2010-09-22 02:33 dir
-rwxr-xr-x 1 root root    5524 2011-01-21 03:54 dmesg
-rwxr-xr-x 1 root root   13824 2010-03-11 03:12 dnsdomainname
-rwxr-xr-x 1 root root   13824 2010-03-11 03:12 domainname
-rwxr-xr-x 1 root root   57940 2010-03-12 15:05 dumpkeys
-rwxr-xr-x 1 root root   30212 2010-09-22 02:33 echo
-rwxr-xr-x 1 root root   39700 2010-03-05 11:47 ed
-rwxr-xr-x 1 root root   96244 2010-03-05 12:48 egrep
-rwxr-xr-x 1

This is a truncated result. I turned on the tcflog to collect TCF agent side logs and got the following result:

TCF 54:25.169: channel server connecting
TCF 54:25.170: channel server connected
TCF 54:26.175: 1: <--- E Locator peerHeartBeat "TCP:128.224.155.39:1534" <eom>
TCF 54:26.175: 1: ---> E Locator peerHeartBeat "TCP:128.224.155.39:1534" <eom>
TCF 54:26.671: channel server connecting
TCF 54:26.671: channel server connected
TCF 54:26.673: 2: ---> C 64 Streams subscribe "Processes" <eom>
TCF 54:26.673: 2: <--- R 64  <eom>
TCF 54:26.675: 2: ---> C 65 Processes getEnvironment <eom>
TCF 54:26.675: 2: <--- R 65  ["TERM=xterm","SHELL=/bin/bash","XDG_SESSION_COOKIE=86013249c25b79f1b600aefb4e38b7c2-1330334696.678017-170175370","SSH_CLIENT=128.224.155.72\x203660\x2022","SSH_TTY=/dev/pts/0","USER=wchen","MAIL=/var/mail/wchen","PATH=.:/folk/wchen/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games","QT_IM_MODULE=ibus","PWD=/folk/wchen/tcf_agent","XMODIFIERS=@im=ibus","LANG=en_US.UTF-8","SPEECHD_PORT=23184","SHLVL=3","HOME=/folk/wchen","LOGNAME=wchen","SSH_CONNECTION=128.224.155.72\x203660\x20128.224.155.55\x2022","GTK_IM_MODULE=ibus","_=/folk/wchen/git/org.eclipse.tcf.agent/agent/obj/GNU/Linux/i686/Debug/agent"] <eom>
TCF 54:26.676: 2: ---> C 66 Processes start "/bin" "/bin/ls" ["/bin/ls","-l"] ["TERM=ansi","SHELL=/bin/bash","SHLVL=3","SPEECHD_PORT=23184","PATH=.:/folk/wchen/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games","SSH_CLIENT=128.224.155.72\x203660\x2022","MAIL=/var/mail/wchen","XDG_SESSION_COOKIE=86013249c25b79f1b600aefb4e38b7c2-1330334696.678017-170175370","USER=wchen","PWD=/folk/wchen/tcf_agent","QT_IM_MODULE=ibus","SSH_TTY=/dev/pts/0","HOME=/folk/wchen","LOGNAME=wchen","GTK_IM_MODULE=ibus","XMODIFIERS=@im=ibus","_=/folk/wchen/git/org.eclipse.tcf.agent/agent/obj/GNU/Linux/i686/Debug/agent","SSH_CONNECTION=128.224.155.72\x203660\x20128.224.155.55\x2022","LANG=en_US.UTF-8"] false <eom>
TCF 54:26.677: 2: <--- E Streams created "Processes" "VS0" "P21134" <eom>
TCF 54:26.677: 2: <--- E Streams created "Processes" "VS1" "P21134" <eom>
TCF 54:26.677: 2: <--- E Streams created "Processes" "VS2" "P21134" <eom>
TCF 54:26.677: 2: <--- R 66  {"Name":"/folk/wchen/git/org.eclipse.tcf.agent/agent/obj/GNU/Linux/i686/Debug/agent","CanTerminate":true,"StdInID":"VS0","StdOutID":"VS1","StdErrID":"VS2","ID":"P21134"} <eom>
TCF 54:26.679: 2: ---> C 67 Streams read "VS2" 512 <eom>
TCF 54:26.680: 2: ---> C 68 Streams read "VS1" 512 <eom>
TCF 54:26.683: 2: <--- R 68 (512)total\x206780\x0a-rwxr-xr-x\x201\x20root\x20root\x20\x20818232\x202010-04-19\x2009:51\x20bash\x0a-rwxr-xr-x\x203\x20root\x20root\x20\x20\x2030200\x202011-12-13\x2006:40\x20bunzip2\x0a-rwxr-xr-x\x201\x20root\x20root\x201269432\x202010-04-23\x2004:04\x20busybox\x0a-rwxr-xr-x\x203\x20root\x20root\x20\x20\x2030200\x202011-12-13\x2006:40\x20bzcat\x0alrwxrwxrwx\x201\x20root\x20root\x20\x20\x20\x20\x20\x20\x206\x202011-12-21\x2011:09\x20bzcmp\x20->\x20bzdiff\x0a-rwxr-xr-x\x201\x20root\x20root\x20\x20\x20\x202140\x202011-12-13\x2006:40\x20bzdiff\x0alrwxrwxrwx\x201\x20root\x20root\x20\x20\x20\x20\x20\x20\x206\x202011-12-21\x2011:09\x20bzegrep\x20->\x20bzgrep\x0a-rwxr-xr-x\x201\x20root\x20root\x20\x20\x20\x204877\x202011-12-13\x2006:40\x20bzexe\x0alrwxrwxrwx\x201\x20root\x20root\x20\x20\x20\x20\x20\x20\x206\x202011-12-21\x201  0 false <eom>
TCF 54:26.683: 2: <--- R 67 null  0 true <eom>
TCF 54:26.683: 2: <--- E Processes exited "P21134" 0 <eom>
TCF 54:26.683: 2: <--- E ProcessesV1 exited "P21134" 0 <eom>
TCF 54:26.684: 2: ---> C 69 Streams read "VS1" 512 <eom>
TCF 54:26.684: 2: <--- R 69 (512)1:09\x20bzfgrep\x20->\x20bzgrep\x0a-rwxr-xr-x\x201\x20root\x20root\x20\x20\x20\x203642\x202011-12-13\x2006:40\x20bzgrep\x0a-rwxr-xr-x\x203\x20root\x20root\x20\x20\x2030200\x202011-12-13\x2006:40\x20bzip2\x0a-rwxr-xr-x\x201\x20root\x20root\x20\x20\x20\x209580\x202011-12-13\x2006:40\x20bzip2recover\x0alrwxrwxrwx\x201\x20root\x20root\x20\x20\x20\x20\x20\x20\x206\x202011-12-21\x2011:09\x20bzless\x20->\x20bzmore\x0a-rwxr-xr-x\x201\x20root\x20root\x20\x20\x20\x201297\x202011-12-13\x2006:40\x20bzmore\x0a-rwxr-xr-x\x201\x20root\x20root\x20\x20\x2050820\x202010-09-22\x2002:33\x20cat\x0a-rwxr-xr-x\x201\x20root\x20root\x20\x20\x2054956\x202010-09-22\x2002:33\x20chgrp\x0a-rwxr-xr-x\x201\x20root\x20root\x20\x20\x2050836\x202010-09-22\x2002:33\x20chmod\x0a-rwxr-xr-x\x201\x20root\x20root\x20\x20\x2054964\x202010-09-  0 false <eom>
TCF 54:26.688: 2: ---> C 70 Streams disconnect "VS2" <eom>
TCF 54:26.688: 2: <--- E Streams disposed "Processes" "VS2" <eom>
TCF 54:26.688: 2: <--- R 70  <eom>
TCF 54:26.689: 2: ---> C 71 Streams read "VS1" 512 <eom>
TCF 54:26.693: 2: <--- R 71 (512)22\x2002:33\x20chown\x0a-rwxr-xr-x\x201\x20root\x20root\x20\x20\x20\x209632\x202010-03-12\x2015:05\x20chvt\x0a-rwxr-xr-x\x201\x20root\x20root\x20\x20\x2096140\x202010-09-22\x2002:33\x20cp\x0a-rwxr-xr-x\x201\x20root\x20root\x20\x20114448\x202010-03-05\x2011:25\x20cpio\x0a-rwxr-xr-x\x201\x20root\x20root\x20\x20\x2083888\x202010-04-02\x2003:22\x20dash\x0a-rwxr-xr-x\x201\x20root\x20root\x20\x20\x2063128\x202010-09-22\x2002:33\x20date\x0a-rwxr-xr-x\x201\x20root\x20root\x20\x20\x20\x209672\x202011-07-23\x2001:02\x20dbus-cleanup-sockets\x0a-rwxr-xr-x\x201\x20root\x20root\x20\x20292728\x202011-07-23\x2001:02\x20dbus-daemon\x0a-rwxr-xr-x\x201\x20root\x20root\x20\x20\x20\x205524\x202011-07-23\x2001:02\x20dbus-uuidgen\x0a-rwxr-xr-x\x201\x20root\x20root\x20\x20\x2054996\x202010-09-22\x2002  0 false <eom>
TCF 54:26.705: 2: ---> C 72 Streams read "VS1" 512 <eom>
TCF 54:26.705: 2: <--- R 72 (512):33\x20dd\x0a-rwxr-xr-x\x201\x20root\x20root\x20\x20\x2067316\x202010-09-22\x2002:33\x20df\x0a-rwxr-xr-x\x201\x20root\x20root\x20\x20104528\x202010-09-22\x2002:33\x20dir\x0a-rwxr-xr-x\x201\x20root\x20root\x20\x20\x20\x205524\x202011-01-21\x2003:54\x20dmesg\x0a-rwxr-xr-x\x201\x20root\x20root\x20\x20\x2013824\x202010-03-11\x2003:12\x20dnsdomainname\x0a-rwxr-xr-x\x201\x20root\x20root\x20\x20\x2013824\x202010-03-11\x2003:12\x20domainname\x0a-rwxr-xr-x\x201\x20root\x20root\x20\x20\x2057940\x202010-03-12\x2015:05\x20dumpkeys\x0a-rwxr-xr-x\x201\x20root\x20root\x20\x20\x2030212\x202010-09-22\x2002:33\x20echo\x0a-rwxr-xr-x\x201\x20root\x20root\x20\x20\x2039700\x202010-03-05\x2011:47\x20ed\x0a-rwxr-xr-x\x201\x20root\x20root\x20\x20\x2096244\x202010-03-05\x2012:48\x20egrep\x0a-rwxr-xr-x\x201  0 true <eom>
TCF 54:26.707: 2: ---> C 73 Streams disconnect "VS1" <eom>
TCF 54:26.707: 2: ---> C 74 Streams disconnect "VS0" <eom>
TCF 54:26.707: 2: <--- E Streams disposed "Processes" "VS1" <eom>
TCF 54:26.707: 2: <--- R 73  <eom>
TCF 54:26.707: 2: <--- E Streams disposed "Processes" "VS0" <eom>
TCF 54:26.707: 2: <--- R 74  <eom>
TCF 54:26.708: 2: ---> C 75 Streams unsubscribe "Processes" <eom>
TCF 54:26.708: 2: <--- R 75  <eom>

Look at the last reading result, i.e., "R 72": the data is apparently not complete, yet it is marked as an ending block (the "true" flag before "<eom>"). That means TCF agent generated a premature end of the output stream of the process "ls". 

I think it should happen in all processes which terminate quickly while generating a lot of output. The standard output is closed at the exit of the program. Yet this is usually too early for a output stream to be flushed. 

Please somebody fix it.
Comment 1 Anna Dushistova CLA 2012-02-28 00:33:41 EST 
I experienced somewhat similar issue while testing bug 37692 with TCF.
Comment 2 Eugene Tarassov CLA 2012-02-28 14:26:16 EST 
Fixed.
Thanks.