log-master fails on log messages larger than 2k in Mac OS X

[gthb]

I can't use --log-master on Mac OS X to pass python logging output (from StreamHandler) through the master, because log messages larger than 2k fail to emit, with "IOError: [Errno 40] Message too long".

Also, messages close to exactly 2k in length sometimes fail with "IOError: [Errno 55] No buffer space available"

Changing setlinebuf(stdout); to setbuf(stdout, (char*)malloc(4096)); in uwsgi.c:1736 makes the former problem (Errno 40) go away; all messages get through. But long messages still get truncated at either 1024, 2048, 3072 or 4096 bytes (and that same "IOError: [Errno 55] No buffer space available" error and stack trace gets printed right after). Making that stdout buffer bigger (even much bigger) does not help.

So it seems like there are two separate problems, both seeming to involve the OS X pipe buffer, and that setlinebuf → setbuf change fixes works around one of them.

[unbit]

Can you attach/paste a sample script to reproduce the problem ? Would help a lot. Even if i am afraid tuning the pipe buffer of OSX from uWSGI will be pretty impossibile, spitting out a warning can be helpful. Thanks

[gthb]

def application(environ, start_response):
    import logging
    for pow in xrange(5, 14):
        numbytes = 1 << pow
        logging.warning('%6d bytes %s' % (numbytes, 'X' * (numbytes - 27)))
    start_response("200 OK", [("Content-Type", "text/plain")])
    return ["pong"]

Run with uwsgi --master --log-master --http-socket :8080 --module uwsgi_issue_75 and then visit localhost:8080 with curl or a browser.

[gthb]

But of course it's not logging-specific, so this test is more direct:

def application(environ, start_response):
    from sys import stdout, stderr
    for pow in xrange(5, 14):
        numbytes = 1 << pow
        try:
            stdout.write('%6d bytes %s\n' % (numbytes, 'X' * (numbytes - 14)))
        except IOError, ioe:
            stderr.write('Errno %d on %d bytes\n' % (ioe.errno, numbytes))
    start_response("200 OK", [("Content-Type", "text/plain")])
    return ["pong"]

... and hey, trying this out I got one case of only 32 bytes coming out, for one message:

  4096 bytes XXXXXXXXXXXXXXXXXXXErrno 55 on 4096 bytes

Before now, I had seen only multiples of 1024 bytes (up to and including 4096).

[unbit]

Are you sure you cannot reproduce the error on Linux ?

Those 1000 bytes limit is hardcoded into python:

(from Python/sysmodule.c)

*** WARNING ***

  The format should limit the total size of the formatted output string to
  1000 bytes.  In particular, this means that no unrestricted "%s" formats
  should occur; these should be limited using "%.<N>s where <N> is a
  decimal number calculated so that <N> plus the maximum size of other
  formatted text does not exceed 1000 bytes.  Also watch out for "%f",
  which can print hundreds of digits for very large numbers.

Can you retry using uwsgi.log() instead of stdout.write() ?

[gthb]

I tried with uwsgi.log() on Linux, but nope, every message gets printed, and truncated consistently at 4096 bytes (or larger if set using --log-master-bufsize).

So I've still seen the problem only on Mac OS X.

[prymitive]

Is this issue report still valid? Does it happen with 1.9?

[gthb]

Please excuse my delayed response — yes, both problems still happen. Here's the “Errno 40” problem exhibited by the second code example above (I've abbreviated long X strings):

$ uwsgi --master --log-master --http-socket :8080 --module uwsgi_issue_75
*** Starting uWSGI 1.9.7 (64bit) on [Tue Apr 23 02:58:54 2013] ***
compiled with version: 4.2.1 Compatible Apple Clang 4.1 ((tags/Apple/clang-421.11.66)) on 23 April 2013 02:58:10
os: Darwin-12.3.0 Darwin Kernel Version 12.3.0: Sun Jan  6 22:37:10 PST 2013; root:xnu-2050.22.13~1/RELEASE_X86_64
nodename: toodee.local
machine: x86_64
clock source: unix
pcre jit disabled
detected number of CPU cores: 8
current working directory: /Users/gthb/svn/datamarket/elam/src
detected binary path: /Users/gthb/pyenv/UW/bin/uwsgi
your processes number limit is 709
your memory page size is 4096 bytes
detected max file descriptor number: 256
lock engine: OSX spinlocks
uwsgi socket 0 bound to TCP address :8080 fd 6
Python version: 2.7.3 (default, Nov 26 2012, 15:40:24)  [GCC 4.2.1 Compatible Apple Clang 4.1 ((tags/Apple/clang-421.11.66))]
*** Python threads support is disabled. You can enable it with --enable-threads ***
Python main interpreter initialized at 0x7f8e5a408bb0
your server socket listen backlog is limited to 100 connections
your mercy for graceful operations on workers is 60 seconds
mapped 145328 bytes (141 KB) for 1 cores
*** Operational MODE: single process ***
WSGI app 0 (mountpoint='') ready in 0 seconds on interpreter 0x7f8e5a408bb0 pid: 10298 (default app)
*** uWSGI is running in multiple interpreter mode ***
spawned uWSGI master process (pid: 10298)
spawned uWSGI worker 1 (pid: 10309, cores: 1)
    32 bytes XXXXXXXXXXXXXXXXXX
    64 bytes XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
   128 bytes XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX[...]
   256 bytes XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX[...]
   512 bytes XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX[...]
  1024 bytes XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX[...]
  2048 bytes XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX[...]
Errno 40 on 4096 bytes
Errno 40 on 8192 bytes
[pid: 10309|app: 0|req: 1/1] 127.0.0.1 () {32 vars in 561 bytes} [Tue Apr 23 02:58:57 2013] GET / => generated 4 bytes in 0 msecs (HTTP/1.1 200) 1 headers in 45 bytes (2 switches on core 0)

and here's the “Errno 55” problem, exhibited by almost the same code, with just this change to try more messages around 2048 bytes:

    for pow in xrange(-15, 15, 3):
        numbytes = 2048 + pow

Output (I've omitted startup loglines and abbreviated long X strings):

  2033 bytes XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX[...]
Errno 55 on 2036 bytes
Errno 55 on 2039 bytes
Errno 55 on 2042 bytes
Errno 55 on 2045 bytes
Errno 55 on 2048 bytes
Errno 40 on 2051 bytes
Errno 40 on 2054 bytes
Errno 40 on 2057 bytes
Errno 40 on 2060 bytes
[pid: 98555|app: 0|req: 1/1] 127.0.0.1 () {32 vars in 561 bytes} [Tue Apr 23 03:08:34 2013] GET / => generated 4 bytes in 2 msecs (HTTP/1.1 200) 1 headers in 45 bytes (2 switches on core 0)
  2033 bytes XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX[...]
  2036 bytes XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX[...]
Errno 55 on 2039 bytes
Errno 55 on 2042 bytes
Errno 55 on 2045 bytes
Errno 55 on 2048 bytes
Errno 40 on 2051 bytes
Errno 40 on 2054 bytes
Errno 40 on 2057 bytes
Errno 40 on 2060 bytes
[pid: 98555|app: 0|req: 2/2] 127.0.0.1 () {30 vars in 492 bytes} [Tue Apr 23 03:08:34 2013] GET /favicon.ico => generated 4 bytes in 834 msecs (HTTP/1.1 200) 1 headers in 45 bytes (2 switches on core 0)

I also tried with a slightly wider and finer-grained range of chunk lengths around 2048:

    for pow in xrange(-25, 25):
        numbytes = 2048 + pow

but then the write to stderr (reporting the IO error that resulted from writing to stdout) fails as well:

  2023 bytes XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX[...]
  2024 bytes XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX[...]
  2025 bytes XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX[...]
Traceback (most recent call last):
  File "./uwsgi_issue_75.py", line 8, in application
    stderr.write('Errno %d on %d bytes\n' % (ioe.errno, numbytes))
IOError: [Errno 55] No buffer space available
[pid: 18280|app: 0|req: 1/1] 127.0.0.1 () {32 vars in 561 bytes} [Tue Apr 23 03:15:42 2013] GET / => generated 0 bytes in 1 msecs (HTTP/1.1 500) 0 headers in 0 bytes (1 switches on core 0)

[unbit]

it took me ages, but i finally found the problem.

Basically the internal buffers created by OSX for socketpair() are extremely tiny (4k). The patch get the size of the uWSGI log buffer and if it is higher than the socketpair() buffer increases it. There is no 1:1 mapping so very probably the logger bufsize should be doubled:

./uwsgi -w foo2 --master --log-master --http-socket :9090 --log-master-buf 16384

(for 8k messages)

another approach i added is creating the socketpair() as a STREAM (like tcp sockets). In such a way the messages will be eventually split:

./uwsgi -w foo2 --master --log-master --http-socket :9090 --log-master-stream

this works pretty badly as logs can be splitted and multiple threads will overlap messages, but could be useful in scenarios where avoiding the exception is better than inconsistent logs.