I able to reproduce it some times if I try posting big error report.
>From worker strace log I see that there is always bad file descriptor
since close() is called twice. Is this uWSGI bug?
This is strace from request that didn't raised rails exception:
write(10, "Completed 200 OK in 153ms (Views"..., 41) = 41
clock_gettime(CLOCK_REALTIME, {1347872907, 401122649}) = 0
writev(11, [{"HTTP/1.1", 8}, {" ", 1}, {"200", 3}, {" ", 1}, {"OK",
2}, {"\r\n", 2}], 6) = 17
writev(11, [{"Content-Type", 12}, {": ", 2}, {"application/xml;
charset=utf-8", 30}, {"\r\n", 2}], 4) = 46
writev(11, [{"X-UA-Compatible", 15}, {": ", 2}, {"IE=Edge,chrome=1",
16}, {"\r\n", 2}], 4) = 35
writev(11, [{"ETag", 4}, {": ", 2},
{"\"cafdfa09bf2adb0bdaddf8b53b214ee"..., 34}, {"\r\n", 2}], 4) = 42
writev(11, [{"Cache-Control", 13}, {": ", 2}, {"max-age=0, private,
must-revalid"..., 35}, {"\r\n", 2}], 4) = 52
writev(11, [{"Set-Cookie", 10}, {": ", 2},
{"_errbit_session=BAh7BkkiD3Nlc3Np"..., 164}, {"\r\n", 2}], 4) = 178
writev(11, [{"X-Request-Id", 12}, {": ", 2},
{"b8ecf7d0301a10e3ffb4ee9ad79be05d", 32}, {"\r\n", 2}], 4) = 48
writev(11, [{"X-Runtime", 9}, {": ", 2}, {"0.189909", 8}, {"\r\n", 2}], 4) = 21
writev(11, [{"X-AppID: 59", 11}, {"\r\n", 2}], 2) = 13
writev(11, [{"X-SDK-Cachable: 0", 17}, {"\r\n", 2}], 2) = 19
write(11, "\r\n", 2) = 2
write(11, "<?xml version=\"1.0\" encoding=\"UT"..., 166) = 166
gettimeofday({1347872907, 402271}, NULL) = 0
open("/proc/self/stat", O_RDONLY) = 18
fstat(18, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x7fb1792f0000
read(18, "109 (uwsgi) R 1 0 0 0 -1 4202560"..., 1024) = 212
close(18) = 0
munmap(0x7fb1792f0000, 4096) = 0
close(18) = -1 EBADF (Bad file descriptor)
munmap(0x7fb1792f1000, 4096) = 0
close(11) = 0
writev(2, [{"{address space usage: 234098688 "..., 78}, {"[pid:
109|app: 0|req: 4/4] () {"..., 208}], 2) = 286
And strace log from request that raised rails exception:
lstat("/home", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat("/home/errbit", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat("/home/errbit/public", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat("/home/errbit/public/notifier_api", 0x7fffef4a4740) = -1 ENOENT
(No such file or directory)
fcntl(18, F_GETFL) = 0x8002 (flags O_RDWR|O_LARGEFILE)
ioctl(18, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fffef4a5680) = -1 ENOTTY
(Inappropriate ioctl for device)
fcntl(2, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK)
ioctl(2, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fffef4a5680) = -1 ENOTTY
(Inappropriate ioctl for device)
clock_gettime(CLOCK_REALTIME, {1347872948, 586989562}) = 0
clock_gettime(CLOCK_REALTIME, {1347872948, 588718552}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2679, ...}) = 0
clock_gettime(CLOCK_REALTIME, {1347872948, 590478273}) = 0
write(10, "\n\nStarted POST \"/notifier_api/v2"..., 89) = 89
fstat(18, {st_mode=S_IFREG|0600, st_size=29754, ...}) = 0
lseek(18, 0, SEEK_CUR) = 0
read(18, "<?xml version=\"1.0\" encoding=\"UT"..., 29754) = 29754
read(18, "", 8192) = 0
brk(0x63bb000) = 0x63bb000
brk(0x63dc000) = 0x63dc000
brk(0x63fd000) = 0x63fd000
brk(0x641e000) = 0x641e000
lseek(18, 0, SEEK_SET) = 0
brk(0x643f000) = 0x643f000
brk(0x6460000) = 0x6460000
brk(0x6481000) = 0x6481000
clock_gettime(CLOCK_REALTIME, {1347872948, 698493120}) = 0
clock_gettime(CLOCK_REALTIME, {1347872948, 699020002}) = 0
clock_gettime(CLOCK_REALTIME, {1347872948, 700832524}) = 0
write(10, "Processing by NoticesController#"..., 46) = 46
close(18) = 0
close(18) = -1 EBADF (Bad file descriptor)
clock_gettime(CLOCK_REALTIME, {1347872948, 844306623}) = 0
write(10, " Parameters: {\"notice\"=>{\"api_k"..., 31287) = 31287
clock_gettime(CLOCK_REALTIME, {1347872948, 845317087}) = 0
clock_gettime(CLOCK_REALTIME, {1347872948, 846574230}) = 0
write(10, "WARNING: Can't verify CSRF token"..., 46) = 46
read(18, 0x6372780, 29754) = -1 EBADF (Bad file descriptor)
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
clock_gettime(CLOCK_REALTIME, {1347872948, 851107208}) = 0
clock_gettime(CLOCK_REALTIME, {1347872948, 851625151}) = 0
write(10, "Completed 500 Internal Server Er"..., 43) = 43
--
Łukasz Mierzwa
_______________________________________________
uWSGI mailing list
[email protected]
http://lists.unbit.it/cgi-bin/mailman/listinfo/uwsgi
