Tracing Python with strace or truss

@brandon_rhodes
PyOhio 2014

What is a system call?

Hundreds of times a second,
your operating system turns over
control of the CPU to a process
Each process is sandboxed
“Python, Linkers, and Virtual Memory”
— PyCon 2012
strace — Linux, thus Ubuntu
truss — BSD, thus Mac OS X

stderr is awesome

$ cat a.html b.html c.html | wc

cat: c.html: No such file or directory
   111     250    5787
       ┌───┐     ┌──┐
TTY  0cat1  0wc1 TTY
       └───┘     └──┘
         2         2
                  

        TTY       TTY
$ cat a.html b.html c.html 2>err | wc >out
$ cat err

cat: c.html: No such file or directory

$ cat out

   111     250    5787
       ┌───┐     ┌──┐
TTY  0cat1  0wc1 ./out
       └───┘     └──┘
         2         2
                  

      ./err     TTY

Why “2>”?

0< — stdin
1> — stdout
2> — stderr
where 1 is the
default for >

So we could:

$ ... | strace python script.py 2>trace.txt | ...
But this would interleave
the trace output with whatever
script.py itself prints to stderr

Instead we will:

$ ... | strace -o trace.txt python script.py | ...
to isolate trace output
in its own separate file
Let’s trace the simplest
possible command

/bin/true

Purpose:
Exit with status 0

process exit status

0 — success
1 — run-time error
2 — bad command line
≥3 — see bash(1) and wait(2)

$?

Status of most recent command
$ grep root /etc/passwd

root:x:0:0:root:/root:/bin/bash

$ echo $?

0

$ grep hamlet /etc/passwd
$ echo $?

1

if

$ if grep -q root /etc/passwd; \
  then echo found; else echo nope; fi

found

$ if grep -q hamlet /etc/passwd; \
  then echo found; else echo nope; fi

nope

Error status

/bin/true
Originally an empty file:
shell script → exit status 0
As AT&T commercialized UNIX,
John Chambers noticed something
/bin/true
#     Copyright (c) 1984 AT&T
#       All Rights Reserved

#     THIS IS UNPUBLISHED PROPRIETARY SOURCE CODE OF AT&T
#     The copyright notice above does not evidence any
#     actual or intended publication of such source code.

#ident        "@(#)cmd/true.sh        50.1"
/bin/true
Has AT&T copyrighted
their own copyright message?
#     Copyright (c) 1984 AT&T
#       All Rights Reserved

#     THIS IS UNPUBLISHED PROPRIETARY SOURCE CODE OF AT&T
#     The copyright notice above does not evidence any
#     actual or intended publication of such source code.

#ident        "@(#)cmd/true.sh        50.1"
#     Copyright (c) 1984 AT&T
#       All Rights Reserved

#     THIS IS UNPUBLISHED PROPRIETARY SOURCE CODE OF AT&T
#     The copyright notice above does not evidence any
#     actual or intended publication of such source code.

#ident        "@(#)cmd/true.sh        50.1"
Or are we violating AT&T copyright
every time we create an empty file?
On my Linux laptop:
$ file /bin/true

/bin/true: ELF 32-bit LSB executable...
$ strace -o trace.txt /bin/true
execve("/bin/true", ["true"], [/* 71 vars */]) = 0
brk(0)                                  = 0x8385000
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
mmap2(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb777d000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=95435, ...}) = 0
mmap2(NULL, 95435, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7765000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/i386-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=1758972, ...}) = 0
mmap2(NULL, 1763964, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb75b6000
mmap2(0xb775f000, 12288, PROT_READ|PROT_WRITE,
      MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1a9000) = 0xb775f000
mmap2(0xb7762000, 10876, PROT_READ|PROT_WRITE,
      MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb7762000
close(3)                                = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb75b5000
set_thread_area({entry_number:-1 -> 6, base_addr:0xb75b5940,
                 limit:1048575, seg_32bit:1, contents:0, read_exec_only:0,
                 limit_in_pages:1, seg_not_present:0, useable:1}) = 0
mprotect(0xb775f000, 8192, PROT_READ)   = 0
mprotect(0x804d000, 4096, PROT_READ)    = 0
mprotect(0xb77a0000, 4096, PROT_READ)   = 0
munmap(0xb7765000, 95435)               = 0
exit_group(0)                           = ?
+++ exited with 0 +++

System calls

0 often means success
-1 often means failure
errno global is set
Documentation:
man 2 write
execve("/bin/true", ["true"], [/* 71 vars */]) = 0
brk(0)                                  = 0x8385000
access("/etc/ld.so.nohwcap", F_OK)
  = -1 ENOENT (No such file or directory)

mmap2(NULL, 8192, PROT_READ|PROT_WRITE,
      MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb777d000

access("/etc/ld.so.preload", R_OK)
  = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3

fstat64(3, {..., st_size=95435, ...}) = 0

mmap2(NULL, 95435, PROT_READ, MAP_PRIVATE, 3, 0)
  = 0xb7765000

close(3) = 0
The life and death of
file descriptor number 3

“Perl Meets Cobol”

“I didn’t have to explain
filehandles; they already knew
about filehandles. But they used
jargon to talk about them that wasn’t
the jargon I was familiar with.
“Oh, you're establishing
addressibility on the file,”
someone said.
—They seemed pleased
at how easy it was … to establish
addressibility on a file.”
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3

lsof

Run lsof -p PID to see a process’s
file descriptors and memory maps
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT

open("/lib/i386-linux-gnu/libc.so.6",
     O_RDONLY|O_CLOEXEC) = 3

read(3, "\177ELF\1\1\1\0\0\0\0\0"..., 512) = 512

fstat64(3, {..., st_size=1758972, ...}) = 0

mmap2(NULL, 1763964, PROT_READ|PROT_EXEC,
      MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb75b6000
mmap2(0xb775f000, 12288, PROT_READ|PROT_WRITE,
      MAP_PRIVATE|..., 3, 0x1a9000) = 0xb775f000
mmap2(0xb7762000, 10876, PROT_READ|PROT_WRITE,
      MAP_PRIVATE|..., -1, 0) = 0xb7762000

close(3) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE,
      MAP_PRIVATE|MAP_ANONYMOUS, -1,
      0) = 0xb75b5000

set_thread_area({entry_number:-1 -> 6,
  base_addr:0xb75b5940, limit:1048575,
  seg_32bit:1, contents:0, read_exec_only:0,
  limit_in_pages:1, seg_not_present:0,
  useable:1}) = 0

mprotect(0xb775f000, 8192, PROT_READ)   = 0
mprotect(0x804d000, 4096, PROT_READ)    = 0
mprotect(0xb77a0000, 4096, PROT_READ)   = 0

munmap(0xb7765000, 95435)               = 0
exit_group(0)                           = ?
+++ exited with 0 +++

noise

execve("/bin/true", ["true"], [/* 71 vars */]) = 0
brk(0)                                  = 0x8385000
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
mmap2(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb777d000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=95435, ...}) = 0
mmap2(NULL, 95435, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7765000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/i386-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=1758972, ...}) = 0
mmap2(NULL, 1763964, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb75b6000
mmap2(0xb775f000, 12288, PROT_READ|PROT_WRITE,
      MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1a9000) = 0xb775f000
mmap2(0xb7762000, 10876, PROT_READ|PROT_WRITE,
      MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb7762000
close(3)                                = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb75b5000
set_thread_area({entry_number:-1 -> 6, base_addr:0xb75b5940,
                 limit:1048575, seg_32bit:1, contents:0, read_exec_only:0,
                 limit_in_pages:1, seg_not_present:0, useable:1}) = 0
mprotect(0xb775f000, 8192, PROT_READ)   = 0
mprotect(0x804d000, 4096, PROT_READ)    = 0
mprotect(0xb77a0000, 4096, PROT_READ)   = 0
munmap(0xb7765000, 95435)               = 0
exit_group(0)                           = ?
+++ exited with 0 +++
“It is a pity that so much tracing
clutter is produced by systems
employing shared libraries.”

strace(2)

$ strace -o trace.txt python3.4 -c ''

507 lines

execve("/usr/bin/python3.4",
       ["python3.4", "-c", ""], [/* 71 vars */])
brk(0)
access("/etc/ld.so.nohwcap", F_OK)
mmap2(NULL, 8192, )
access("/etc/ld.so.preload", R_OK)
open("/etc/ld.so.cache", ) = 3
fstat64(3, {, st_size=95435, })
mmap2(NULL, 95435, )
close(3)
                        

7 times:

                        
access("/etc/ld.so.nohwcap", F_OK)
open("/lib/i386-linux-gnu/libpthread.so.0", )
read(3, "\177ELF\1\1\1\0", 512)
fstat64(3, {, st_size=130518, })
mmap2(NULL, 111276, )
mmap2(0xb776e000, 8192, )
mmap2(0xb7770000, 4780, )
close(3)
                        
$ which python3.4
/usr/bin/python3.4
$ ldd /usr/bin/python3.4
        linux-gate.so.1 => ...
        libpthread.so.0 => ...
        libc.so.6 => ...
        libdl.so.2 => ...
        libutil.so.1 => ...
        libexpat.so.1 => ...
        libz.so.1 => ...
        libm.so.6 => ...
        /lib/ld-linux.so.2 (0xb77da000)

After further memory-map shenanigans:

open("/dev/urandom",
     O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 3
fcntl64(3, F_GETFD) = 0x1 (flags FD_CLOEXEC)
read(3, "…", 24) = 24
close(3)

Then the Python runtime gets serious:

stat64("/home/brandon/bin/python3.4", ) = -1
stat64("/home/brandon/usr/bin/python3.4", ) = -1
stat64("/usr/local/sbin/python3.4", ) = -1
stat64("/usr/local/bin/python3.4", ) = -1
stat64("/usr/sbin/python3.4", ) = -1
stat64("/usr/bin/python3.4",
       {, st_size=3802224, }) = 0
readlink("/usr/bin/python3.4", , 4096) = -1

the result is stored as sys.executable

Python checks for a few config files

open("/usr/bin/pyvenv.cfg", ) = -1 ENOENT
open("/usr/pyvenv.cfg", ) = -1 ENOENT
stat64("/usr/bin/Modules/Setup", ) = -1 ENOENT
The standard library is discovered
through a search for nearby lib directories
stat64("/usr/bin/lib/python3.4/os.py", ) = -1
stat64("/usr/bin/lib/python3.4/os.pyc", ) = -1
stat64("/usr/lib/python3.4/os.py",
       {, st_size=33618, }) = 0
(That is why virtualenv copies os.py)

Finally, import can start its work

stat64("/usr/lib/python3.4/encodings"
        "/__init__.cpython-34m-i386-linux-gnu.so",
       ) = -1
stat64("/__init__.cpython-34m.so", ) = -1
stat64("/__init__.abi3.so", ) = -1
stat64("/__init__.so", ) = -1
stat64("/__init__.py", ) = 0
stat64("/__init__.py", ) = 0
open("/__pycache__/__init__.cpython-34.pyc", ) = 3

How many filenames does Python try?

m directories × n extensions

System Python:

$ python3.4 -c 'import sys, pprint;\
                pprint.pprint(sys.path)'
['',
 '/usr/lib/python3.4',
 '/usr/lib/python3.4/plat-i386-linux-gnu',
 '/usr/lib/python3.4/lib-dynload',
 '/usr/local/lib/python3.4/dist-packages',
 '/usr/lib/python3/dist-packages']

Python in a virtualenv:

$ bin/python3.4 -c 'import sys,pprint;\
                    pprint.pprint(sys.path)'
['',
 '…venv/lib/python3.4',
 '…venv/lib/python3.4/plat-i386-linux-gnu',
 '…venv/lib/python3.4/lib-dynload',
 '/usr/lib/python3.4',
 '/usr/lib/python3.4/plat-i386-linux-gnu',
 '/home/brandon/p/lib/python3.4/site-packages',
 '/usr/lib/python3/dist-packages',
 '/usr/local/lib/python3.4/dist-packages']

After easy_install of some eggs:

$ easy_install zc.recipe.egg

$ bin/python3.4 -c 'import sys,pprint;\
                    pprint.pprint(sys.path)'
['',
 '…venv/…/site-packages/zc.recipe.egg-2.0.1-py3.4.egg',
 '…venv/…/site-packages/zc.buildout-2.2.1-py3.4.egg',
 '…venv/lib/python3.4',
 '…venv/lib/python3.4/plat-i386-linux-gnu',
 '…venv/lib/python3.4/lib-dynload',
 '/usr/lib/python3.4',
 '/usr/lib/python3.4/plat-i386-linux-gnu',
 '/home/brandon/v/lib/python3.4/site-packages',
 '/usr/lib/python3/dist-packages',
 '/usr/local/lib/python3.4/dist-packages']
The combination of Zope plus
easy_install was a perfect storm
$ grokenv/bin/easy_install grok



$ grokenv/bin/python2.7 -c \
  'import sys; print(len(sys.path))'

183
Longer sys.path generates more
system calls for each import
strace -c ...

Counts system calls

strace -e open,stat64 ...

Filter system calls

$ strace -c -e open,stat64 \
  /usr/bin/python2.7 -c 'import popen2'

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- -------
 70.11    0.000258           1       276       206 open
 29.89    0.000110           1       102        66 stat64
------ ----------- ----------- --------- --------- -------
100.00    0.000368                   378       272 total
$ strace -c -e open,stat64 \
  venv/bin/python2.7 -c 'import popen2'

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- -------
 72.73    0.000947           3       292       237 open
 27.27    0.000355           2       222       117 stat64
------ ----------- ----------- --------- --------- -------
100.00    0.001302                   514       354 total
$ strace -c -e open,stat64 \
  grokenv/bin/python2.7 -c 'import popen2'

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- -------
 72.42    0.013402           3      4290      4232 open
 27.58    0.005104           4      1417       879 stat64
------ ----------- ----------- --------- --------- -------
100.00    0.018506                  5707      5111 total
How long do those
5,707 system calls take?
$ time -p /usr/bin/python2.7 -c 'import popen2'

real 0.03
user 0.03
sys 0.00

$ time -p grokenv/bin/python2.7 -c 'import popen2'

real 0.13
user 0.05
sys 0.07

Note

That was from merely
having Grok installed
import popen2
What if we actually
imported Grok?

O()

$ strace -c -e open,stat64 \
  grokenv/bin/python2.7 -c 'import grok'

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- -------
 79.56    0.163195           3     59704     58917 open
 20.44    0.041926           3     13773     11972 stat64
------ ----------- ----------- --------- --------- -------
100.00    0.205121                 73477     70889 total
Always use
pip and virtualenv

Two approaches

easy_install
Everything in system site-packages,
then mix-and-match with sys.path
/site-packages/Django-1.3-py2.7.egg/django/
/site-packages/Django-1.5-py2.7.egg/django/
/site-packages/Django-1.6-py2.7.egg/django/
virtualenv and pip
Separate environments, each with
a single django directly installed
/venv/python2.7/site-packages/django/
Always use
pip
~
Always use
virtualenv
$ strace -c -e open,stat64 \
  /usr/bin/python2.7 -c 'import email'

% time     seconds  usecs/call     calls    errors syscall

100.00    0.000000                   384       275 total

$ strace -c -e open,stat64 \
  /usr/bin/python3.4 -c 'import email'

% time     seconds  usecs/call     calls    errors syscall

100.00    0.000000                   148        24 total

Debugging

These stacks of stat() and
open() calls give great info
import example
import example
import example
Note that a Python import can
trigger dynamic library loading!
import ssl
ssl.py
_ssl.so
libssl.so.1.0.0
libcrypto.so.1.0.0
PEP 302
PEP 328
Once your application
is imported and running,
what calls will you see?

1 : 1

Many os and socket routines
map directly to system calls
import os
os.mkdir("d")
       
mkdir("d", 0777)
       
import socket
s = socket.socket()
                    
socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 3
                    
import os
os.write(1, "hello\n")
           
write(1, "hello\n", 6) = 6
           

1 : many

Other Python operations
generate several calls
import os
os.listdir("/")
               
openat(AT_FDCWD, "/", ...) = 3
getdents64(3, /* 27 entries */, 32768)  = 720
getdents64(3, /* 0 entries */, 32768)   = 0
close(3)                                = 0
               
import socket
socket.getaddrinfo("google.com", "www")
open("/etc/resolv.conf", O_RDONLY|O_CLOEXEC) = 3
                       
             (20 more system calls)
                       
open("/etc/gai.conf", O_RDONLY|O_CLOEXEC)    = 3
                       
             (18 more system calls)
                       
socket(PF_INET, SOCK_DGRAM|, IPPROTO_IP)    = 3
connect(3, {sa_family=AF_INET, sin_port=htons(53),
        sin_addr=inet_addr("127.0.1.1")}, 16) = 0
                       
             (35 more system calls)

Manual section 2 vs 3

$ man mkdir

Whoops! Section 1 is shell commands:

MKDIR(1)     User Commands    MKDIR(1)

NAME
       mkdir - make directories

SYNOPSIS
       mkdir [OPTION]... DIRECTORY...

DESCRIPTION
       Create  the  DIRECTORY(ies), if
       they do not already exist.
$ man -s 2,3 mkdir

or, if you already have a guess:

$ man 2 mkdir         # system call: simple
$ man 3 getaddrinfo   # libc function: compound

1 : nothing!

Sometimes an action
can seem to have no
immediate result!
import sys, time
print "Hello",
sys.stdout.write("world.")
time.sleep(100)
Process makes no
attempt to output!

Buffering

Not an OS feature,
but a behavior of:
Buffering makes I/O more efficient
print
stdout.write()
stderr.write()
another_file.write()
compared to raw I/O

os.write()

print "a",
print "b",
print "c"
          
write(1, "a b c\n", 6)
          

Buffering

flushing

import sys
print "a",
sys.stdout.flush()
print "b"
       
write(1, "a", 1)
write(1, " b\n", 3)
       

turn off buffering

$ python -u ...
$ export PYTHONUNBUFFERED=True

or even

sys.stdout = os.fdopen(sys.stdout.fileno(), 'w', 0)
When does buffered output
flush() on its own?

After newline, when writing to terminal:

for i in range(10000):
    print 'Number',
    print i
          
write(1, "Number 0\n", 9)
write(1, "Number 1\n", 9)
write(1, "Number 2\n", 9)
          
write(1, "Number 9999\n", 12)
          

Every block, when writing to file:

for i in range(10000):
    print 'Number',
    print i
          
write(1, "Number 0\nNumber 1\nNumber 2\n"..., 4096)
write(1, "er 382\nNumber 383\nNumber 384"..., 4096)
write(1, "54\nNumber 755\nNumber 756\nNu"..., 4096)
          
write(1, "mber 9991\nNumber 9992\nNumber"..., 106)
          
How does Python tell?
import sys
sys.stdout.isatty()

import os
os.isatty(1)
ioctl(1,
      SNDCTL_TMR_TIMEBASE
      or SNDRV_TIMER_IOCTL_NEXT_DEVICE
      or TCGETS,
      {B38400 opost isig icanon echo...}) = 0

Threads

Like a new process,
but lives in the same
memory sandbox
import threading
threading.Thread().start()

clone(child_stack=0xb70f6424,
      flags=CLONE_VM|CLONE_FS|CLONE_FILES
           |CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM
           |CLONE_SETTLS|CLONE_PARENT_SETTID
           |CLONE_CHILD_CLEARTID, ...) = 13496

Process

Run a different executable
inside a new memory sandbox
import os
os.spawnvp(os.P_WAIT, "ls", ["ls"])

clone(child_stack=0, flags=CLONE_CHILD_CLEARTID
      |CLONE_CHILD_SETTID|SIGCHLD, ...) = 13703

And then what?

Use strace -f to follow each
child thread created by clone()
import os
os.spawnvp(os.P_WAIT, "ls", ["ls"])

13742 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID
            |CLONE_CHILD_SETTID|SIGCHLD, ...) = 13743

13743 execve("/bin/ls", ["ls"], [/* 70 vars */]) = 0
13743 brk(0)                             = 0x90b4000
13743 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT

import os
os.system("ls")

1915 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID
           |CLONE_CHILD_SETTID|SIGCHLD, ...) = 1916
1915 wait4(-1,  <unfinished ...>
1916 execve("/bin/ls", ["ls"], [/* 79 vars */]) = 0
1916 brk(0)                            = 0x90b4000
1916 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT

1916  +++ exited with 0 +++
1915  <... waitpid resumed>
      [{WIFEXITED(s) == 0}], 0, NULL) = 1916

subprocess operations are
even more complicated
call()
check_call()
check_output()
Popen()

Advice

Always compare your trace
to a working example

Common debugging

Running out of memory

Running out of file descriptors

More options

ltrace

Even slower:
traces library calls
Useful for SSL, when
strace can only show:
                      
write(3, "\27\3\3\0`\342\243\357\314\ndk"..., 101)
read(3, "\27\3\3\4\343", 5)
read(3, "\0\0\0\0\0\0\0\1\262/\264\254\0"..., 1251)
                      

ssl_test.py

import urllib
urllib.urlopen('https://www.google.com/').read()

ltrace.conf

int SSL_write(void, string, uint)
$ ltrace -F ltrace.conf -s 9999 \
    -l 'libssl*' -o ltrace.txt \
    python2.7 -c ssl_test.py
_ssl.i386-linux-gnu.so->SSL_write(
  "GET / HTTP/1.0\r\nHost: www.google.com\r\n"
  "User-Agent: Python-urllib/1.17\r\n\r\n",
  72) = 72
strace
ltrace
truss

@brandon_rhodes