connection failure after "tcp: remove max_qlen_log"

From: Kui Zhang
Date: Sat Jan 23 2016 - 18:54:54 EST

Next message: Florian Westphal: "Re: net: GPF in netlink_getsockbyportid"
Previous message: Martin Roth: "[PATCH] 82xx: FCC: Fixing a bug causing to FCC port lock-up (second try)"
Next in thread: Eric Dumazet: "Re: connection failure after "tcp: remove max_qlen_log""
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

Hello,

One of our java software would not start after this:

# first bad commit: [ef547f2ac16bd9d77a780a0e7c70857e69e8f23f] tcp:
remove max_qlen_log

Log from software:

STATUS | monitor | 2016/01/23 14:22:55 | Launching a Service...
INFO | buserver | 2016/01/23 14:23:00 | WrapperManager class
initialized by thread: main Using classloader:
sun.misc.Launcher$AppClassLoader@2876b359
INFO | buserver | 2016/01/23 14:23:00 |
INFO | buserver | 2016/01/23 14:23:00 | Wrapper Manager: JVM #1
INFO | buserver | 2016/01/23 14:23:00 | Running a 64-bit JVM.
INFO | buserver | 2016/01/23 14:23:00 | Wrapper Manager: Registering
shutdown hook
INFO | buserver | 2016/01/23 14:23:00 | Wrapper Manager: Using wrapper
INFO | buserver | 2016/01/23 14:23:00 | Load native library. One or
more attempts may fail if platform specific libraries do not exist.
INFO | buserver | 2016/01/23 14:23:00 | Loading native library
failed: libwrapper-linux-x86-64.so Cause:
java.lang.UnsatisfiedLinkError: no wrapper-linux-x86-64 in
java.library.path
INFO | buserver | 2016/01/23 14:23:00 | Loaded native library: libwrapper.so
INFO | buserver | 2016/01/23 14:23:00 | Calling native initialization method.
INFO | buserver | 2016/01/23 14:23:00 | Inside native WrapperManager
initialization method
INFO | buserver | 2016/01/23 14:23:00 | Java Version :
1.7.0_80-b15 Java HotSpot(TM) 64-Bit Server VM
INFO | buserver | 2016/01/23 14:23:00 | Java VM Vendor : Oracle Corporation
INFO | buserver | 2016/01/23 14:23:00 |
INFO | buserver | 2016/01/23 14:23:00 |
WrapperManager.start(com.r1soft.backup.server.BUServerWrapper@7e515f40,
args["wait"]) called by thread: main
INFO | buserver | 2016/01/23 14:23:00 | Open socket to
wrapper...Wrapper-Connection
ERROR | monitor | 2016/01/23 14:23:24 | Startup failed: Timed out
waiting for a signal from the Service.

### normal output around this point
### INFO | buserver | 2016/01/23 14:30:57 | Opened Socket from 31000 to 32000

ADVICE | monitor | 2016/01/23 14:23:24 |
ADVICE | monitor | 2016/01/23 14:23:24 |
------------------------------------------------------------------------
ADVICE | monitor | 2016/01/23 14:23:24 | Advice:
ADVICE | monitor | 2016/01/23 14:23:24 | The Wrapper consists of a
native component as well as a set of classes
ADVICE | monitor | 2016/01/23 14:23:24 | which run within the Service
that it launches. The Java component of the
ADVICE | monitor | 2016/01/23 14:23:24 | Wrapper must be initialized
promptly after the Service is launched or the
ADVICE | monitor | 2016/01/23 14:23:24 | Wrapper will timeout, as
just happened. Most likely the main class
ADVICE | monitor | 2016/01/23 14:23:24 | specified in the Wrapper
configuration file is not correctly initializing
ADVICE | monitor | 2016/01/23 14:23:24 | the Wrapper classes:
ADVICE | monitor | 2016/01/23 14:23:24 | Main
ADVICE | monitor | 2016/01/23 14:23:24 | While it is possible to do
so manually, the Wrapper ships with helper
ADVICE | monitor | 2016/01/23 14:23:24 | classes to make this
initialization processes automatic.
ADVICE | monitor | 2016/01/23 14:23:24 | Please review the
integration section of the Wrapper's documentation
ADVICE | monitor | 2016/01/23 14:23:24 | for the various methods
which can be employed to launch an application
ADVICE | monitor | 2016/01/23 14:23:24 | within the Wrapper:
ADVICE | monitor | 2016/01/23 14:23:24 |
http://wrapper.tanukisoftware.org/doc/english/integrate.html
ADVICE | monitor | 2016/01/23 14:23:24 |
------------------------------------------------------------------------
ADVICE | monitor | 2016/01/23 14:23:24 |
ERROR | monitor | 2016/01/23 14:23:24 | JVM did not exit on request,
terminated
DEBUG | monitor | 2016/01/23 14:23:24 | Signal trapped. Details:
DEBUG | monitor | 2016/01/23 14:23:24 | signal number=17
(SIGCHLD), source="unknown"
DEBUG | monitor | 2016/01/23 14:23:24 | Received SIGCHLD, calling wait().
DEBUG | monitor | 2016/01/23 14:23:24 | wait() returned, child
process should be gone.
STATUS | monitor | 2016/01/23 14:23:24 | Service Restarts disabled.
Shutting down.
STATUS | monitor | 2016/01/23 14:23:24 | <-- Monitor Stopped

strace snippet:

10685 nanosleep({0, 100000000}, <unfinished ...>
10684 <... nanosleep resumed> NULL) = 0
10684 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 4
10684 fcntl(4, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
10684 bind(4, {sa_family=AF_INET, sin_port=htons(32000),
sin_addr=inet_addr("127.0.0.1")}, 16) = 0
10684 stat("/etc/localtime", {st_dev=makedev(9, 2), st_ino=1828322,
st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096,
st_blocks=8, st_size=2875, st_atime=2015/10/13-11:06:06,
st_mtime=2015/10/13-11:06:06, st_ctime=2015/10/13-11:06:06}) = 0
10684 listen(4, 0) = 0
10684 accept(4, 0x7ffcae409990, [16]) = -1 EAGAIN (Resource
temporarily unavailable)
10684 write(3, "STATUS | monitor | 2016/01/22 15:28:05 | --> Monitor
Started as Daemon\nDEBUG | monitor | 2016/01/22 15:28:05 | Using
tick timer.\nDEBUG | monitorp | 2016/01/22 15:28:05 | server
listening on port 32000.\n", 206) = 206
10684 nanosleep({0, 100000000}, <unfinished ...>
10685 <... nanosleep resumed> NULL) = 0
10685 nanosleep({0, 100000000}, <unfinished ...>
10684 <... nanosleep resumed> NULL) = 0
10684 accept(4, 0x7ffcae409990, [16]) = -1 EAGAIN (Resource
temporarily unavailable)
10684 stat("/etc/localtime", {st_dev=makedev(9, 2), st_ino=1828322,
st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096,
st_blocks=8, st_size=2875, st_atime=2015/10/13-11:06:06,
st_mtime=2015/10/13-11:06:06, st_ctime=2015/10/13-11:06:06}) = 0

10684 <... nanosleep resumed> NULL) = 0
10684 read(5, 0x7ffcae4095c0, 1024) = -1 EAGAIN (Resource
temporarily unavailable)
10684 accept(4, <unfinished ...>
10686 lstat("/usr", <unfinished ...>
10684 <... accept resumed> 0x7ffcae409990, [16]) = -1 EAGAIN (Resource
temporarily unavailable)
10686 <... lstat resumed> {st_dev=makedev(9, 2), st_ino=5922817,
st_mode=S_IFDIR|0755, st_nlink=11, st_uid=0, st_gid=0,
st_blksize=4096, st_blocks=8, st_size=4096,
st_atime=2010/04/27-15:01:55, st_mtime=2012/07/19-10:30:24,
st_ctime=2012/07/19-10:30:24}) = 0
10684 wait4(10686, <unfinished ...>

10684 read(5, 0x7ffcae4095c0, 1024) = -1 EAGAIN (Resource
temporarily unavailable)
10684 accept(4, 0x7ffcae409990, [16]) = -1 EAGAIN (Resource
temporarily unavailable)
10684 wait4(10686, 0x7ffcae409a04, WNOHANG, NULL) = 0
10684 nanosleep({0, 100000000}, <unfinished ...>
10702 <... futex resumed> ) = -1 ETIMEDOUT (Connection timed out)
10702 futex(0x23b8128, FUTEX_WAKE_PRIVATE, 1) = 0
10702 futex(0x23b8154, FUTEX_WAIT_BITSET_PRIVATE, 1, {3795,
461801741}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
10702 futex(0x23b8128, FUTEX_WAKE_PRIVATE, 1) = 0
10702 futex(0x23b8154, FUTEX_WAIT_BITSET_PRIVATE, 1, {3795,
511937320}, ffffffff <unfinished ...>
10703 <... futex resumed> ) = -1 ETIMEDOUT (Connection timed out)
10703 futex(0x2a49428, FUTEX_WAKE_PRIVATE, 1) = 0
10703 futex(0x2a49454, FUTEX_WAIT_BITSET_PRIVATE, 1, {3795,
577866793}, ffffffff <unfinished ...>
10695 <... futex resumed> ) = -1 ETIMEDOUT (Connection timed out)
10695 futex(0x237ea28, FUTEX_WAKE_PRIVATE, 1) = 0
10695 futex(0x237ea54, FUTEX_WAIT_BITSET_PRIVATE, 1, {3796,
488884445}, ffffffff <unfinished ...>
10685 <... nanosleep resumed> NULL) = 0
10685 nanosleep({0, 100000000}, <unfinished ...>
10684 <... nanosleep resumed> NULL) = 0
10684 read(5, 0x7ffcae4095c0, 1024) = -1 EAGAIN (Resource
temporarily unavailable)
10684 accept(4, 0x7ffcae409990, [16]) = -1 EAGAIN (Resource
temporarily unavailable)
10684 wait4(10686, 0x7ffcae409a04, WNOHANG, NULL) = 0
10684 nanosleep({0, 100000000}, <unfinished ...>
10702 <... futex resumed> ) = -1 ETIMEDOUT (Connection timed out)
10702 futex(0x23b8128, FUTEX_WAKE_PRIVATE, 1) = 0
10702 futex(0x23b8154, FUTEX_WAIT_BITSET_PRIVATE, 1, {3795,
562081947}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
10702 futex(0x23b8128, FUTEX_WAKE_PRIVATE, 1) = 0
10702 futex(0x23b8154, FUTEX_WAIT_BITSET_PRIVATE, 1, {3795,
612211605}, ffffffff <unfinished ...>
10703 <... futex resumed> ) = -1 ETIMEDOUT (Connection timed out)
10703 futex(0x2a49428, FUTEX_WAKE_PRIVATE, 1) = 0
10703 futex(0x2a49454, FUTEX_WAIT_BITSET_PRIVATE, 1, {3795,
678010858}, ffffffff <unfinished ...>
10685 <... nanosleep resumed> NULL) = 0
10685 nanosleep({0, 100000000}, <unfinished ...>
10684 <... nanosleep resumed> NULL) = 0
10684 read(5, 0x7ffcae4095c0, 1024) = -1 EAGAIN (Resource
temporarily unavailable)
10684 accept(4, 0x7ffcae409990, [16]) = -1 EAGAIN (Resource
temporarily unavailable)

thanks
Kui.Z

Next message: Florian Westphal: "Re: net: GPF in netlink_getsockbyportid"
Previous message: Martin Roth: "[PATCH] 82xx: FCC: Fixing a bug causing to FCC port lock-up (second try)"
Next in thread: Eric Dumazet: "Re: connection failure after "tcp: remove max_qlen_log""
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]