Skip to content

HTTPS clone URL

Subversion checkout URL

You can clone with HTTPS or Subversion.

Download ZIP

Loading…

localtime (in P_LOG_TO macro) is not threadsafe, causes SIGSEGV in HelperServer #599

Closed
FooBarWidget opened this Issue · 10 comments

1 participant

@FooBarWidget

From beth.macgibbon on June 03, 2010 23:53:02

What steps will reproduce the problem? 1. Run Passenger 2.2.13 + REE on FreeBSD 8 w/ ENOTCONN fixes and LD_BIND_NOW=yes
2. Load a page that uses lots of X-Accel-Redirect headers
3. HelperServer will core dump, and Nginx returns 404s for any further requests What is the expected output? What do you see instead? Expect to see messages such as this logged in the NGINX error log:

[ pid=24988 file=ext/nginx/HelperServer.cpp:478 time=.381 ]:
Couldn't forward the HTTP response back to the HTTP client: It seems the user clicked on the 'Stop' button in his browser.
[ pid=24988 file=ext/nginx/HelperServer.cpp:485 time=.745 ]:
Uncaught exception in PassengerServer client thread:
exception: write() failed: Socket is not connected (57)
backtrace:
in 'void Client::forwardResponse(boost::shared_ptrPassenger::Application::Session&, FileDescriptor&)' (HelperServer.cpp:376)
in 'void Client::handleRequest(FileDescriptor&)' (HelperServer.cpp:460)
in 'void Client::threadMain()' (HelperServer.cpp:506)

Instead I get a SIGSEGV with a backtrace that looks like:

[root@p2198956 /opt/ruby-enterprise-1.8.7-2010.01/lib/ruby/gems/1.8/gems/passenger-2.2.13]# gdb ext/nginx/HelperServer ./HelperServer.core
GNU gdb 6.1.1 [FreeBSD]
Copyright 2004 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and you are
welcome to change it and/or distribute copies of it under certain conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB. Type "show warranty" for details.
This GDB was configured as "amd64-marcel-freebsd"...
Core was generated by `HelperServer'.
Program terminated with signal 11, Segmentation fault.
Reading symbols from /lib/libthr.so.3...done.
Loaded symbols for /lib/libthr.so.3
Reading symbols from /usr/lib/libstdc++.so.6...done.
Loaded symbols for /usr/lib/libstdc++.so.6
Reading symbols from /lib/libm.so.5...done.
Loaded symbols for /lib/libm.so.5
Reading symbols from /lib/libgcc_s.so.1...done.
Loaded symbols for /lib/libgcc_s.so.1
Reading symbols from /lib/libc.so.7...done.
Loaded symbols for /lib/libc.so.7
Reading symbols from /libexec/ld-elf.so.1...done.
Loaded symbols for /libexec/ld-elf.so.1
#0 0x0000000800cbab57 in timeoff () from /lib/libc.so.7
[New Thread 800f06600 (LWP 100254)]
[New Thread 800f067c0 (LWP 100253)]
[New Thread 800f06980 (LWP 100252)]
[New Thread 800f06b40 (LWP 100251)]
[New Thread 800f06d00 (LWP 100250)]
[New Thread 800f06ec0 (LWP 100249)]
[New Thread 800f07080 (LWP 100248)]
[New Thread 800f07240 (LWP 100247)]
[New Thread 800f07400 (LWP 100246)]
[New Thread 800f075c0 (LWP 100245)]
[New Thread 800f07780 (LWP 100244)]
[New Thread 800f07940 (LWP 100243)]
[New Thread 800f07b00 (LWP 100242)]
[New Thread 800f07cc0 (LWP 100241)]
[New Thread 800f07e80 (LWP 100240)]
[New Thread 800f08040 (LWP 100239)]
[New Thread 800f08200 (LWP 100238)]
[New Thread 800f083c0 (LWP 100237)]
[New Thread 800f08580 (LWP 100236)]
[New Thread 800f08740 (LWP 100235)]
[New Thread 800f08900 (LWP 100233)]
[New Thread 800f08ac0 (LWP 100231)]
[New Thread 800f08c80 (LWP 100189)]
[New Thread 800f08e40 (LWP 100181)]
[New Thread 800f511c0 (LWP 100161)]
[New Thread 800f51380 (LWP 100158)]
New Thread 800f021c0 (LWP 100198) bt full
#0 0x0000000800cbab57 in timeoff () from /lib/libc.so.7
No symbol table info available.
#1 0x0000000800cba58e in timeoff () from /lib/libc.so.7
No symbol table info available.
#2 0x0000000800cbb266 in timeoff () from /lib/libc.so.7
No symbol table info available.
#3 0x0000000800cbb5f6 in gmtime_r () from /lib/libc.so.7
No symbol table info available.
#4 0x0000000800cbbcba in localtime () from /lib/libc.so.7
No symbol table info available.
#5 0x000000000043a9ff in Client::handleRequest (this=0x800f9e180, clientFd=@0x7fffffbccc20) at ext/nginx/HelperServer.cpp:476
tv = {tv_sec = 5677952, tv_usec = 34376606752}
sstream = {std::basic_iostream<char,std::char_traits<char >> = {std::basic_istream<char,std::char_traits<char >> =
{std::basic_ios<char,std::char_traits<char >> = {std::ios_base = {
_vptr$ios_base = 0x800989708, static boolalpha = std::_S_boolalpha, static dec = std::_S_dec, static fixed = std::_S_fixed, static hex =
std::_S_hex, static internal = std::_S_internal,
static left = std::_S_left, static oct = std::_S_oct, static right = std::_S_right, static scientific = std::_S_scientific, static showbase =
std::_S_showbase,
static showpoint = std::_S_showpoint, static showpos = std::_S_showpos, static skipws = std::_S_skipws, static unitbuf = std::_S_unitbuf, static
uppercase = std::_S_uppercase,
static adjustfield = std::_S_adjustfield, static basefield = std::_S_basefield, static floatfield = std::_S_floatfield, static badbit = std::_S_badbit, static
eofbit = std::_S_eofbit,
static failbit = std::_S_failbit, static goodbit = std::_S_goodbit, static app = std::_S_app, static ate = std::_S_ate, static binary = std::_S_bin, static in
= std::_S_in,
static out = std::_S_out, static trunc = std::_S_trunc, static beg = std::_S_beg, static cur = std::_S_cur, static end = std::_S_end, _M_precision = 6,
_M_width = 0, _M_flags = 4098,
_M_exception = std::_S_goodbit, _M_streambuf_state = std::_S_goodbit, _M_callbacks = 0x0, _M_word_zero = {_M_pword = 0x0, _M_iword = 0},
_M_local_word = {{_M_pword = 0x0, _M_iword = 0}, {
_M_pword = 0x0, _M_iword = 0}, {_M_pword = 0x0, _M_iword = 0}, {_M_pword = 0x0, _M_iword = 0}, {_M_pword = 0x0, _M_iword = 0},
{_M_pword = 0x0, _M_iword = 0}, {_M_pword = 0x0,
_M_iword = 0}, {_M_pword = 0x0, _M_iword = 0}}, _M_word_size = 8, _M_word = 0x7fffffbcc2b8, _M_ios_locale = {static none = 0, static ctype
= 1, static numeric = 2,
static collate = 4, static time = 8, static monetary = 16, static messages = 32, static all = 63, _M_impl = 0x8009aa7a0, static _S_classic =
,
static _S_global = , static _S_categories = , static _S_once = }}, _M_tie = 0x0, _M_fill = 0 '\0',
_M_fill_init = false,
_M_streambuf = 0x7fffffbcc228, _M_ctype = 0x8009aa9e0, _M_num_put = 0x8009aac70, _M_num_get = 0x8009aac60}, _vptr$basic_istream =
0x8009896b8,
_M_gcount = 0}, std::basic_ostream<char,std::char_traits<char >> = {_vptr$basic_ostream = 0x8009896e0}, },
_M_stringbuf = {std::basic_streambuf<char,std::char_traits<char >> = {_vptr$basic_streambuf = 0x800989a90, _M_in_beg = 0x0, _M_in_cur =
0x0, _M_in_end = 0x0, _M_out_beg = 0x0,
_M_out_cur = 0x0, _M_out_end = 0x0, _M_buf_locale = {static none = 0, static ctype = 1, static numeric = 2, static collate = 4, static time = 8, static
monetary = 16, static messages = 32,
static all = 63, _M_impl = 0x8009aa7a0, static _S_classic = , s...

Original issue: http://code.google.com/p/phusion-passenger/issues/detail?id=499

@FooBarWidget

From beth.macgibbon on June 03, 2010 15:17:58

Actually, having just put a mutex around it... it might not be a threading issue... but the crash is still there
anyway

@FooBarWidget

From honglilai on June 03, 2010 15:25:11

I'm not all that familiar with FreeBSD. If someone has any clue why that code crashes
I'd like to know.

@FooBarWidget

From honglilai on June 03, 2010 15:31:15

Does using the reentrant version help?

diff --git a/ext/common/Logging.h b/ext/common/Logging.h
index 35bcaa5..26940c5 100644
--- a/ext/common/Logging.h
+++ b/ext/common/Logging.h
@@ -80,13 +80,13 @@ void setDebugFile(const char *logFile = NULL);
do { \
if (stream != 0) { \
time_t the_time; \

  • struct tm *the_tm; \
  • struct tm the_tm; \ char datetime_buf[60]; \ struct timeval tv; \ std::stringstream sstream; \ \ the_time = time(NULL); \
  • the_tm = localtime(&the_time); \
  • the_tm = localtime_r(&the_time, &the_tm); \ strftime(datetime_buf, sizeof(datetime_buf), "%F %H:%M:%S", the_tm); \ gettimeofday(&tv, NULL); \ sstream << \
@FooBarWidget

From honglilai on June 03, 2010 15:33:12

That doesn't compile. This does. :)

diff --git a/ext/common/Logging.h b/ext/common/Logging.h
index 35bcaa5..7c93e89 100644
--- a/ext/common/Logging.h
+++ b/ext/common/Logging.h
@@ -80,14 +80,14 @@ void setDebugFile(const char *logFile = NULL);
do { \
if (stream != 0) { \
time_t the_time; \

  • struct tm *the_tm; \
  • struct tm the_tm; \ char datetime_buf[60]; \ struct timeval tv; \ std::stringstream sstream; \ \ the_time = time(NULL); \
  • the_tm = localtime(&the_time); \
  • strftime(datetime_buf, sizeof(datetime_buf), "%F %H:%M:%S", the_tm); \
  • localtime_r(&the_time, &the_tm); \
  • strftime(datetime_buf, sizeof(datetime_buf), "%F %H:%M:%S", &the_tm); \ gettimeofday(&tv, NULL); \ sstream << \ "[ pid=" << ((unsigned long) getpid()) << \
@FooBarWidget

From beth.macgibbon on June 03, 2010 15:54:30

(gdb) bt full
#0 0x0000000800cbab57 in timeoff () from /lib/libc.so.7
No symbol table info available.
#1 0x0000000800cba58e in timeoff () from /lib/libc.so.7
No symbol table info available.
#2 0x0000000800cbb266 in timeoff () from /lib/libc.so.7
No symbol table info available.
#3 0x0000000800cbb5f6 in gmtime_r () from /lib/libc.so.7
No symbol table info available.
#4 0x0000000800cbb9f2 in localtime_r () from /lib/libc.so.7
No symbol table info available.
#5 0x000000000043a9ec in Client::handleRequest (this=0x800f9e180, clientFd=@0x7fffffbccc40) at
ext/nginx/HelperServer.cpp:476

Pretty much same crash...

@FooBarWidget

From honglilai on June 03, 2010 16:17:43

I'm wondering whether this wouldn't be a stack size issue. Try increasing
HelperServer.cpp's CLIENT_THREAD_STACK_SIZE.

@FooBarWidget

From beth.macgibbon on June 03, 2010 16:29:49

I increased it to 128k and it seems to have fixed it, I get proper error logs now:

[ pid=25883 file=ext/nginx/HelperServer.cpp:485 time=2010-06-04 11:28:39.93 ]:
Uncaught exception in PassengerServer client thread:
exception: write() failed: Socket is not connected (57)
backtrace:
in 'void Client::forwardResponse(boost::shared_ptrPassenger::Application::Session&, FileDescriptor&)' (HelperServer.cpp:376)
in 'void Client::handleRequest(FileDescriptor&)' (HelperServer.cpp:460)
in 'void Client::threadMain()' (HelperServer.cpp:506)

Interestingly, I tried to replicate it on a FreeBSD 9-CURRENT machine and couldn't

@FooBarWidget

From honglilai on June 03, 2010 16:41:38

I guess some localtime() implementations need a lot of stack. Does 96k also work?

Marking this issue for 2.2.13.

Labels: Milestone-2.2.13

@FooBarWidget

From beth.macgibbon on June 03, 2010 16:50:02

I've tried, 96, 80 and 72. They all work, perhaps it's related to the size of:

[root@p2198956 ~]# ls -l /etc/localtime
-r--r--r-- 1 root wheel 2434 Jun 4 17:04 /etc/localtime

On an Ubuntu 10.04 machine /etc/localtime is only 882 bytes (for the same timezone NZST)

@FooBarWidget

From honglilai on June 04, 2010 03:13:25

Fixed in commit 73f59cd.

Status: Fixed

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Something went wrong with that request. Please try again.