我们有一个在Tomcat6(准确地说是6.0.35.0)上运行的应用程序,并且由于Catalina.await方法中的socketAccept调用引发SocketException,因此MacOS上的大多数工程师在启动Tomcat时遇到问题:
SEVERE: StandardServer.await: accept: java.net.SocketException: Invalid argument at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.socketAccept(PlainSocketImpl.java) at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:398) at java.net.ServerSocket.implAccept(ServerSocket.java:522) at java.net.ServerSocket.accept(ServerSocket.java:490) at org.apache.catalina.core.StandardServer.await(StandardServer.java:431) at org.apache.catalina.startup.Catalina.await(Catalina.java:676) at org.apache.catalina.startup.Catalina.start(Catalina.java:628) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:601) at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:289) at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:414) at mycompany.tomcat.startup.ThreadDumpWrapper.main(ThreadDumpWrapper.java:260) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:601) at org.tanukisoftware.wrapper.WrapperStartStopApp.run(WrapperStartStopApp.java:238) at java.lang.Thread.run(Thread.java:722)
这将导致Tomcat在启动后立即关闭(并且不会造成任何愤怒)。我们认为,在使用Java 1.7的Mac OS上,这种情况一直存在,在过去的几个月中,我们中的许多人都改用了Macbook Pro。到目前为止,唯一的症状是来自Tomcat的偶尔零字节响应,因为此异常也抛出在socketRead上。错误不会出现在日志中,我们将其作为一个孤立的问题单独耸耸肩,只有在启动问题开始并且我设置了SocketException断点时才找到原因:
Daemon Thread [http-8080-1] (Suspended (breakpoint at line 47 in SocketException)) SocketException.<init>(String) line: 47 SocketInputStream.socketRead0(FileDescriptor, byte[], int, int, int) line: not available [native method] SocketInputStream.socketRead0(FileDescriptor, byte[], int, int, int) line: not available SocketInputStream.read(byte[], int, int, int) line: 150 SocketInputStream.read(byte[], int, int) line: 121 InternalInputBuffer.fill() line: 735 InternalInputBuffer.parseRequestLine() line: 366 Http11Processor.process(Socket) line: 814 Http11Protocol$Http11ConnectionHandler.process(Socket) line: 602 JIoEndpoint$Worker.run() line: 489 Thread.run() line: 722
对于参数:
arg0 FileDescriptor (id=499) fd 1097 useCount AtomicInteger (id=503) value 2 arg1 (id=502) arg2 0 arg3 8192 arg4 20000
问题是时间敏感的。由于应用程序更改而导致的启动时间增加(很多Spring内省/单例开销)似乎是导致其影响Tomcat启动的因素。临界点大约为160秒。我们可以通过禁用一些在开发过程中不需要的非强制性上下文来减少启动时间,从而减轻问题的发生,但是我更希望找到根本原因。
该应用程序的细节过于复杂,以至于无法进行过多的详细介绍,但是我有一种直觉,即这可能与早期的绑定有关,因此我至少要列出机器上的侦听端口:
localhost:32000 - Java service wrapper port *:10001 - RMI registry *:2322 - Java debug *:56566 - RMI *:8180 - Tomcat HTTP connector *:8543 - Tomcat HTTPS connector *:2223 - Tomcat Internal HTTP connector (used for cross-server requests) *:14131 - 'Locking' port to determine if an internal service is running *:56571 - EhCache RMI *:56573 - RMI *:62616 - ActiveMQ broker *:5001 - SOAPMonitorService *:8109 - Tomcat shutdown port
-Djava.net.preferIPv4Stack=true
5000
10000
/etc/hosts
对于那些对主机配置感兴趣的人,它与默认设置相同。我可以在带有10.8的全新安装的Fusion VM上重现此内容:
## # Host Database # # localhost is used to configure the loopback interface # when the system is booting. Do not change this entry. ## 127.0.0.1 localhost 255.255.255.255 broadcasthost ::1 localhost fe80::1%lo0 localhost
由于问题的时间敏感性很强,因此设置断点对问题进行故障排除不会导致问题的发生。根据评论中的要求,我也捕获arg0了SocksSocketImpl(PlainSocketImpl).socketAccept(SocketImpl),似乎没有什么异常。
arg0
SocksSocketImpl(PlainSocketImpl).socketAccept(SocketImpl)
arg0 SocksSocketImpl (id=460) address InetAddress (id=465) canonicalHostName null holder InetAddress$InetAddressHolder (id=475) address 0 family 0 hostName null applicationSetProxy false closePending false cmdIn null cmdOut null cmdsock null CONNECTION_NOT_RESET 0 CONNECTION_RESET 2 CONNECTION_RESET_PENDING 1 external_address null fd FileDescriptor (id=713) fd -1 useCount AtomicInteger (id=771) value 0 fdLock Object (id=714) fdUseCount 0 localport 0 port 0 resetLock Object (id=716) resetState 0 server null serverPort 1080 serverSocket null shut_rd false shut_wr false socket Socket (id=718) bound false closed false closeLock Object (id=848) connected false created false impl null oldImpl false shutIn false shutOut false socketInputStream null stream false timeout 0 trafficClass 0 useV4 false
我认为引发异常的所有线程都是较早调用的受害者,该调用不会导致SocketException,因此我无法捕获它。能够通过减少启动时间来启动Tomcat,这使我确信,触发器可能是一些计划的任务,该任务执行基于套接字的操作,然后会影响其他套接字操作。
但这并不能解释这将如何以及为什么会影响多个线程,无论我们采取什么措施导致这种情况,神秘的SocketException都不应从本机代码中冒出,并在多个线程上同时导致这些异常- 即两个线程反复进行传出Web服务调用,Tomcat等待调用和多个TP处理器线程。
给定该通用消息,我假定EINVAL必须从socketAccept JNI代码中的一个系统调用返回错误,因此我跟踪了导致异常的系统调用。没有EINVAL任何系统调用返回。因此,我去了OpenJDK源,在socketAccept代码中查找会设置条件然后抛出的条件EINVAL,但我也找不到任何设置errno为EINVAL,或调用的代码NET_ThrowByNameWithLastError,NET_ThrowCurrent或者NET_ThrowNew以这种方式抛出SocketException的方式默认错误消息。
EINVAL
errno
NET_ThrowByNameWithLastError
NET_ThrowCurrent
NET_ThrowNew
就系统调用而言,我们似乎还没有达到accept系统调用:
PID/THRD RELATIVE ELAPSD CPU SYSCALL(args) = return 6606/0x2c750d: 221538243 5 0 sigprocmask(0x1, 0x0, 0x14D8BE100) = 0x0 0 6606/0x2c750d: 221538244 3 0 sigaltstack(0x0, 0x14D8BE0F0, 0x0) = 0 0 6606/0x2c750d: 221538836 14 10 socket(0x2, 0x1, 0x0) = 1170 0 6606/0x2c750d: 221538837 3 0 fcntl(0x492, 0x3, 0x4) = 2 0 6606/0x2c750d: 221538839 3 1 fcntl(0x492, 0x4, 0x6) = 0 0 6606/0x2c750d: 221538842 5 2 setsockopt(0x492, 0xFFFF, 0x4) = 0 0 6606/0x2c750d: 221538852 7 4 bind(0x492, 0x14D8BE5D8, 0x10) = 0 0 6606/0x2c750d: 221538857 5 2 listen(0x492, 0x1, 0x4) = 0 0 6606/0x2c750d: 221539625 6 2 psynch_cvsignal(0x7FEFBFE00868, 0x10000000200, 0x100) = 257 0 6606/0x2c750d: 221539633 4 1 write(0x2, "Apr 18, 2013 11:05:35 AM org.apache.catalina.core.StandardServer await\nSEVERE: StandardServer.await: accept: \njava.net.SocketException: Invalid argument\n\tat java.net.PlainSocketImpl.socketAccept(Native Method)\n\tat java.net.PlainSocketImpl.socketAcce", 0x644) = 1604 0
因此,我 认为 问题出在中的accept循环顶部的超时处理代码中socketAccept,但是我找不到NET_Timeout将设置errno为的任何情况EINVAL,并导致抛出此SocketException。我指的是这段代码;我认为jdk7u分支大部分是Oracle JDK中附带的:
socketAccept
NET_Timeout
在MacOS上,我找不到外界受到此特定问题影响的任何人,但是这里的几乎每个人都受到影响。必须有一些有助于应用程序的配置,但是我想出了找到根本原因的各种方法,已经用尽了。
有关故障排除或对可能原因的见解的指针将不胜感激。
您是否尝试过打开JNI调试用-Xcheck:jni?有趣的是,Oracle文档使用PlainSocketImpl.socketAccept错误作为何时使用此错误的示例。
-Xcheck:jni
PlainSocketImpl.socketAccept
还要注意,错误7131399的含义是,由于Mac上的问题,JNI poll()在大多数平台select()上使用,但在Mac OS poll()上使用。所以也许select()也坏了。再深入一点,如果“ ndfs大于FD_SETSIZE且未定义_DARWIN_UNLIMITED_SELECT,则select()将返回EINVAL。” FD_SETSIZE为1024,这听起来像您有大量的应用程序正在加载,因此也许所有这些都过滤掉了,一次只能等待1024个以上的FD。
poll()
select()
为了获得更多的荣誉,请查看您的计算机上实际上是否已修复了相关的(据说已修复)Java错误。错误报告具有指向测试用例的指针。
感谢Old Pro的回答,我确认select()FD_SETSIZE限制是原因。我为此限制找到了一个现有的错误:
https://bugs.openjdk.java.net/browse/JDK-8021820
可以使用以下代码重现该问题:
import java.io.*; import java.net.*; public class SelectTest { public static void main(String[] args) throws Exception { // Use 1024 file descriptors. There'll already be some in use, obviously, but this guarantees the problem will occur for(int i = 0; i < 1024; i++) { new FileInputStream("/dev/null"); } ServerSocket socket = new ServerSocket(8080); socket.accept(); } }
差不多一年后,Java 7u60修复了此问题:
http://www.oracle.com/technetwork/java/javase/2col/7u60-bugfixes-2202029.html
我还发现Tomcat的WebappClassLoader在90秒后关闭了文件句柄,这解释了为什么设置断点可以防止此问题发生。