0

I'm trying to debug a program that generates a lot of data. But the event which I want to debug happens after a random amount of time (I cannot force it). So I would need to see the stdout and stderr in my shell and save the same output to a file for further analysis and interrupt as soon as I see what I need on my shell output.

I found the script command on this ask Ubuntu thread but I cannot get it to work, script says :

$ script "./client -p 4242 -n test"
Script started, output file is ./client -p 4242 -n test

and then exits. The file contains:

Script started on Thu Jun 26 13:51:12 2014

Script done on Thu Jun 26 13:51:12 2014

So script doesn't work. The ./client file is a python script. I also tried launching it with $ python client -p 4242 -n test but it's not working either.

I also saw on the same thread some answers with tee and a pipe but I can't get it to output to my shell and see what is going on:

$ ./client -p 4242 -n test | tee output.log

gives me a waiting cursor without nothing happening. So tee doesn't work.

Is there any other solution or am I doomed to wait and interrupt the program after some time and hope it went through the event I'm looking for ?

Thank you much for your help !

P.S. I'm on zshell (with oh-my-zsh), Mac OSX 10.9.3, Python 2.7.5

EDIT: I may have to mention I'm using the multiprocessing module and the ./client script launches multiple other Processes. Could it be for that reason ? Still I don't understand why it won't catch the ./client process output...

EDIT2: I tried the answer from Matteo below (thanks a lot for your help) and it keeps getting stranger and stranger:

If the process fails (the server is shutdown), I can see the output:

$ ./client -p 4242 -n test 2>&1 | tee output.log
Process Process-1:
Client # 1: Could not connect to server. Stopping.
Spawner: New client # 1 started...
Done.
$

but if it looks like it's running, I see nothing:

$ ./client -p 4242 -n test 2>&1 | tee output.log
^C [voluntary interrupt after a lot of waiting]
$ cat output.log
$ 

In the log above (where it fails), you can see that the new process prints before the main one (Spawner) even though it started after it. So it looks like some really strange output magic.

  • If tee and script aren't capturing the program's output, then the program may be doing something more "clever" than just write to stdout/stderr. It may be writing to /dev/tty, or it may alter its behavior when stdout/stderr isn't a TTY. – Kenster Jun 26 '14 at 13:36
  • The only function I'm using is the print statement from Python (2.7.5). – achedeuzot Jun 26 '14 at 13:40
2

You can redirect standard error to standard output and then use tee to duplicate standard output and store it to a file.

$ ./client -p 4242 -n test 2>&1  | tee output.log

Edit: you can try out the command by

$ ( echo "stdout" ; echo "stderr" 1>&2 ) 2>&1  | tee output.log

The two echos produce output on both stdout and stderr. You should see both, and the same in output.log

Edit

Instead of modifying your program (flush) you could also try script -q or several other tools as mentioned in Turn off buffering in pipe

  • I tried this because it was suggested in the ask Ubuntu thread but there is no output on the shell when I try it. And the output.log file is empty ! I don't understand why :/ Is it the python 2.7 "print" statement ? – achedeuzot Jun 26 '14 at 13:03
  • 1
    @matteo's answer is the normal way to do what you've asked. It's possible that this "client" program behaves differently when stdout/stderr isn't a TTY. – Kenster Jun 26 '14 at 13:29
  • BTW I tested on OS X 10.9.3 with zsh and it's behaving as described. – Matteo Jun 26 '14 at 13:58
  • Thanks so much for your help. Unfortunately, it keeps getting more and more strange (see second edit). I'll wait some more in case someone knows where this could be coming from (python ? multiprocess ?). – achedeuzot Jun 26 '14 at 15:30
  • Your answer is the correct one in a "general case". But didn't work for me because of some specificities (Python multiprocessing module). – achedeuzot Jun 26 '14 at 15:57
1

Victory !

As mentioned in the question, I was using python's multiprocessing.Process to spawn new processes from the main client. Because of that, the output was buffered and waited for the buffer to be full before flushing but it seems that it never happens with the | tee command. Thus never printing anything and waiting endlessly.

Thus, the solution is to add a sys.stdout.flush() after every print statement as mentioned here:

print "Player # " + int(self.id) + " joined the map"
sys.stdout.flush() #<==== THIS MAKES IT ALL WORK !

After that, Matteo's answer works like a charm and it's possible to have the output on the shell and in the text file at the same time.

$ ./client -p 4242 -n test 2>&1  | tee output.log`
$ cat output.log
Player # 1 joined the map.
Player # 1 updated it's inventory.
[...]

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.