[ts-gen] redirecting shim output to python script

[Mike Thornton]

Hi folks,

I am still having a bit of difficultly reading data from a pipe when a test
python script connects to the shim.  The script basically polls the pipe for
data and reads it when available.  What I observe is that my python script
(code below) does not fully read all of the initial shim account header
information.  After reading a total of about 8kB of data, the script enters
a state where it continually polls an empty pipe -- the rest of the usual
header info is not read.  What I suspect is happening is that there is a
buffer overflow with the pipe.  I understand that linux 2.6 kernels (what I
have) have 64kB allocated to pipes with a maximum of 4kB for each atomic
access.  The last few lines printed out are shown below.  Is it possible
that the shim is writing more than 4kB to the pipe at once, thereby causing
the script to lose the tail of the header?  The header prints out just fine
if I run the shim command line without a script wrapper, and the script is
not locking up since it ends up continually polling an empty pipe...


Thanks.
Mike



-------------------------- last several shim lines printed by
script-------------------------
poll = [(5, 1)]
3510|44731|   4169714|3| 6| 2|GrossPositionValue-S            |     0.00|USD
|DU11111|
poll = [(5, 1)]
3510|44731|   4169733|3| 6| 2|InitMarginReq                   |     0.83|USD
|DU11111|
poll = [(5, 1)]
3510|44731|   4169751|3| 6| 2|InitMarginReq-C                 |     0.00|USD
|DU11111|
poll = [(5, 1)]
3510|44731|   4169775|3| 6| 2|InitMarginReq-S                 |     0.83|USD
|DU11111|
poll = [(5, 1)]
3510|44731|   4169791|3| 6| 2|Leverage-S                      |     0.00|
|DU11111|
poll = []
poll = []
poll = []
poll = []
poll = []
poll = []

------------------------ Python script ------------------------------------
import subprocess
import select
import time

if __name__ == '__main__':
    shimProcess = subprocess.Popen('/usr/local/shim/shim --risk cout file
save', bufsize=1, shell=True, stdin=subprocess.PIPE, stdout=subprocess.PIPE,
stderr=subprocess.STDOUT)
    shimPoll = select.epoll()
    shimPoll.register(shimProcess.stdout)
    while True:
        a = shimPoll.poll(0)
        print "poll = %s" % a
        while (len(a) == 0):
            time.sleep(0.05)
            a = shimPoll.poll(0)
            print "poll = %s" % a
        line = shimProcess.stdout.readline().strip()
        print line
-------------------------------------------------------------

On Wed, May 6, 2009 at 10:12 AM, Bill Pippin <pippin at owlriver.net> wrote:

> Mike,
>
> Glad to hear from you.  About your python code, I don't routinely
> program in python, since I prefer Ruby, so I might miss some fine
> details in your code.  So, others with more facility in python
> should feel free to contribute as well.
>
> You ask about the "once" option:
>
> > What does the 'once' statement -- copied from /exs/kill.rb -- do?
>
> The once option ensures that in risk mode, the shim tries to connect
> to the upstream IB tws exactly once; without it, a risk mode shim
> can try to connect up to eight times, incrementing the client id each
> time.
>
> Since the downstream needs to know the client id in order to refer
> to orders in future sessions, some users will want to prevent such
> retries, and the "once" option allows you to do this, though at the
> cost of possibly having the shim terminate with an
> ib_tws_handshake_failure exception, number 523, with text message:
> "the IB tws server handshake failed".
>
> About your popen call:
>
> > ... is the following call correct ...
>
>    0. > self.shimProcess = subprocess.Popen(
>    1. > '/usr/local/shim --risk cout save once',
>    2. > bufsize=0,
>    3. > shell=True,
>    4. > stdin=subprocess.PIPE,
>    5. > stdout=subprocess.PIPE,
>    6. > stderr=subprocess.STDOUT)
>
> In the text above, I've added the line numbers as references.  As for
> line [0], you definitely want a popen; I use a similar approach with
> Ruby, and this approach is applicable for other scripting languages as
> well.
>
>    2. > bufsize=0,
>    3. > shell=True,
>
> I would suggest you ultimately change to bufsize=1, to get line
> buffered input, which is, after all, the way the shim is sending
> it to your script, although you probably want to stick with
> unbuffered IO as long as you are debugging.  The use of shell=true
> makes sense to me as long as your're working on Unix, though
> python programmers may want to chime in here.
>
> > ... so that the shim input/output is logged in a file?
>
>    1. > '/usr/local/shim --risk cout save once',
>
> Do you want the shim output to be logged to a file, as well as
> over a pipe?  If so, you should say so, by including the file
> option.  The file and cout options are old, and so are covered
> in the manual, in the help, and with the file option used as well
> in both risk.rb and test.rb.
>
> With no log option, neither file, nor cout, nor logd, the shim
> insists on opening a log file anyway.  Otherwise, if you use any
> non-empty subset of these three options, the shim takes you at your
> word, and logs to just the ones you ask for.  If you want log
> output to be directed only to the stdout, then the "cout" option
> is just what you need.
>
>    4. > stdin=subprocess.PIPE,
>    5. > stdout=subprocess.PIPE,
>    6. > stderr=subprocess.STDOUT)
>
> Once given "cout", and ignoring the question of a log file for now,
> then if the python plumbing in [4-6] is what you want, and lines [4-5]
> give you a full-duplex pipe, you need to get ahold of your ends of
> the pipe file descriptors, and be writing to, and reading from,
> subprocess.PIPE[1] and subprocess.PIPE[0], or whatever the correct
> python syntax for those endpoints is.
>
> Consider similar code in ruby, adapted from exs/loop.rb:
>
>    path = "/home/pippin/tsi"
>    prog = "shim --data file cout save"
>    exec = "#{path}/#{prog}"
>
>    shim = IO.popen(exec, "w+");
>    shim.puts                                  "wait  4;\n";
>    shim.puts "select acct;                     wait  0;\n"
>    shim.puts "select next;                     wait  1;\n"
>    shim.puts "cancel acct;                     wait  0;\n"
>    shim.puts "select next;                     wait  0;\n"
>    shim.puts "select open;                     wait  1;\n"
>    shim.puts "select time;"
>    shim.puts "select bars STK:SMART:AMAT:USD;\nwait 20;\n"
>    shim.puts "cancel bars STK:SMART:AMAT:USD;\nwait 10;\n"
>    shim.puts "exit;\n"
>    shim.close_write
>    while line = shim.gets do
> #     puts line                 # can trace shim output here
>    end
>
> In the code above, shim is a full-duplex file handle returned
> by IO.popen.  The waits are not necessary, but are for user
> convenience in debugging; I'm reading the stderr, and using a
> shim monitor via tail(1) processing as this runs, about which
> more below, and it's easier to assign credit/blame if the script
> is stepping through its commands to the shim.
>
> Its essential that puts come before gets.  It's very easy here
> to write code that deadlocks, and you may want to consider using
> select, in Ruby terms IO.select(), to either time out your read
> on the pipe stdin, or multiplex your reads on the pipe stdin and
> the subprocess stderr, or both.
>
> Buffering may also give you headaches; just because you've put to
> the pipe doesn't mean the text has been sent on to the child shim.
> Presumably you already know this, since you had bufsize=0 in your
> call.  In the above Ruby script, I have to use shim.close_write
> or some other command that causes a flush of the write channel in
> order to prevent deadlock.
>
> > I am having a little difficulty in redirecting the shim output to
> > a python subprocess.  From print statements, I can see that the
> > shim output is not making it into the python script.
>
> Yes, but why?  Because the python plumbing is set wrong, or your
> script does not include code to read the PIPE[0] fd, or there is
> no input on that descriptor, or your script has deadlocked?
>
> You should be able to verify to your own satisfaction that a
> shim process with the cout option produces output --- with tick
> subscriptions, copious output --- on the stdout.  Once given
> such a test, then the problem *must* lie in your script.
>
> In that case the questions I raise above are of interest, and
> in particular the last two raise the issue of deadlock, always
> a likely cause of problems when using full-duplex pipes.
>
> Ultimately deadlock --- and again, deadlock is the most likely
> reason not to see input --- is a script debugging problem, and
> although you are free to post to this list with such questions,
> please understand that I personally will not be free to debug
> your python scripts for you.
>
> You may want to run the pure shim regression scripts in exs, that
> is the four character file names not having a file extension, and
> (as noted in exs/Readme) validated via the script exs/prog.sh.
>
> You also probably want to have a separate, tail'd konsole open
> while you run these scripts, using, say,
>
>    bin/tail.window log/ShimText 2
>
> This should allow you to know what exactly the shim is writing.
> Once you begin debugging your own scripts, you should provide
> both the file and cout options to the shim subprocess, and use
> the bin/tail.window script to monitor the shim.  That way, when
> you run into deadlock, you have some hope of guessing where
> and when it occurred.
>
> In particular, this shim-monitor approach will help you see that
> such deadlocks aren't in the shim.  It just keeps on ticking; if
> it has connected to a working IB tws, and gets valid command
> input, the related requests go upstream, and the resulting
> messages come flooding back.
>
> Thanks,
>
> Bill
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://www.trading-shim.org/pipermail/ts-general/attachments/20090513/7dd03d4e/attachment-0001.html