目前Apache + Weblogic Cluster是很多企业应用的架构模式,前端Apache负责请求分发,后端利用Weblogic Cluster的session replication提供failover。绝大多数情况下,这种模式工作的很好。这篇文章我将以标题中的两个名词为中心,探讨一下Apache plugin的分发及failover机制。首先看一下这两个名词:
No backend server available:没有可用的后端服务器。最常见最可能的原因就是:后端server全部没有启动或者Apache无法连接到其中的任何一个。复现方式很简单,只启动Apache,然后做后端weblogic server的业务请求,或者中断Apache到后端服务器的网络。这种原因很好检查,也很好解决。本文中我们将探讨另外一种情况,网络没有问题,而且至少有一个服务器存活,但客户端仍然碰到“No backend server available”。
HALF_OPEN_SOCKET_RETRY:Weblogic内部自定的异常,这种异常通常由于Apache使用了某个已经中断的连接向后端服务器发送请求,这种请求肯定会失败。连接中断的原因也很多,比如我们关闭后端的服务器,那么Apache手里到这个服务器的连接再次被使用时,Apache将会收到HALF_OPEN_SOCKET_RETRY。
首先,我们看一下plugin的分发机制。通常每个非初始请求都会在自己的cookie中有一个JSESSIONID,JSESSIONID由weblogic产生,用户唯一标识和该用户相关的Session。JSessionID常见格式为:
SessionHash ! primaryHash ! SecondaryHash,比如:
s4wYKyvDKG2ZDHwQclchD50PYjvCsN9nLSL9hPRMQ2ZzM3pVdbL1!1198345223!-977705075
primary:该Session的主服务器
secondary:该Session的备份服务器,如果没做SessionReplication,则没有该列。如果SessionReplication失败,那么该列会是none或null。
有了JSESSIONID,在load_utils.getPreferredServersFromCookie()中,plugin会解析这个JSESSIONID,如果我们打开plugin的debug,我们会看到类似如下的信息,
Thu Sep 10 08:56:36 2009 <1899912525369961> Found cookie from cookie header: JSESSIONID=s4wYKyvDKG2ZDHwQclchD50PYjvCsN9nLSL9hPRMQ2ZzM3pVdbL1!1198345223!-977705075
Thu Sep 10 08:56:36 2009 <1899912525369961> Parsing cookie JSESSIONID=s4wYKyvDKG2ZDHwQclchD50PYjvCsN9nLSL9hPRMQ2ZzM3pVdbL1!1198345223!-977705075
Thu Sep 10 08:56:36 2009 <1899912525369961> getpreferredServersFromCookie: [1198345223!-977705075]
Thu Sep 10 08:56:36 2009 <1899912525369961> primaryJVMID: [1198345223]
secondaryJVMID: [-977705075]
解析出了primaryJVMID、secondaryJVMID,这是plugin需要检查这两个id是否为空,如果两个都为空,那么说明这个请求没有prefer server,plugin只要按照最基本的load balance策略作请求分发即可。如果至少有一个不为空,我们继续找该session所prefer的server,debug 信息如下:
Thu Sep 10 08:56:36 2009 <1899912525369961>Primary or Secondary JVMID *not* found in cookie, ignore preferred servers //说明没有从cookie中找到primay或secondary。
Thu Sep 10 08:56:36 2009 <1899912525369961> No of JVMIDs found in cookie: 2 //说明找到了两个jvmID
Apache plugin运行过程中会维护一个server list,这个server list就是我们在httpd.conf中指定的server列表,如果我们使用了dynamic server list,那么这个list是随着后端cluster的变化而动态更新的。server list中每个server有自己的JVMID。plugin从cookie中解析出primaryJVMID、secondaryJVMID后,需要primaryJVMID、secondary JVMID做校验,防止cookie中的信息过于陈旧(如果后端服务器发生过重起,就会出现JVMID不一致的情况)。校验过程其实很简单,plugin会遍历手里的server list。如果发现某个server被标志为bad,它会检查skip-time,如果skip-time(默认10秒)已到,即从这个server被mark bad到现在已经超过10秒,那么plugin会把这个server重新mark good(这样如果我们接下来创建到这个server的连接成功,那这个server就真的可用了,plugin通过这种机制来恢复后端server)。
1 time_t t = lists[i].startMarkBad;
2 if (t > 0) {
3 time_t now = 0;
4 time(&now);
5 int delta = now - t;
6 if (delta >= MAX_SKIP_TIME) {
7 lists[i].startMarkBad = 0;
8 lists[i].isGood = 1;
9 }
10 }
接着plugin会将解析出来的primaryJVMID、secondaryJVMID后自己server list中server的JVMID做比对。如果primary匹配,就把对应的serverInfo设入请求的preferred[0],同样如果seconday匹配,对应的serverInfo会被设入请求的preferred[1]。注意:接下来plugin将以preferred为基础进行分发、failover。debug信息如下:
Wed Sep 02 14:33:12 2009 <553612518731924> getPreferredFromCookie: Found Primary 172.23.4.53:8001:0
Wed Sep 02 14:33:12 2009 <553612518731924> getPreferredFromCookie: Found Secondary 172.23.4.52:8001:0
如果匹配的server数目和cookie中jvmid数一致,则还能看到如下输出:
Wed Sep 02 14:33:12 2009 <553612518731924> getPreferredFromCookie: Found 2 servers
如果不匹配,那么输出信息将是下面这样:
Wed Sep 02 14:33:12 2009 <553612518731924> getPreferredFromCookie: Found atleast 1 server
如果匹配结果发现没有一致的JVMID,如下:
Thu Sep 10 08:56:36 2009 <1899912525369961> getPreferredFromCookie: Either JVMIDs not set or they are stale. Will try to get JVMIDs from WLS
那么这时候plugin就需要强制更新自己server list中server的JVMID,这个更新通过proxy.initJVMID()实现。initJVMID中,plugin遍历整个server list,尝试创建到每个server的连接,如果连接创建失败,这个server会被mark bad。连接创建成功,plugin向后端server发送internal request,如下:
Thu Sep 10 08:56:36 2009 <1899912525369961> ======internal request /bea_wls_internal/ WLDummyInitJVMIDs======
如果连接能够成功创建,但发送请求的时候发生HALF_OPEN_SOCKET_RETRY(这里为什么会发送HALF_OPEN_SOCKET_RETRY,后面我们会讨论到),这个server也会被mark bad(这里对HALF_OPEN_SOCKET_RETRY的处理不同于应用请求),如下:
Thu Sep 10 08:56:36 2009 <1899912525369961> readStatus: Local port of the socket 53149, connected to Remote Host/Port 172.23.4.53/8001
Thu Sep 10 08:56:36 2009 <1899912525369961> readStatus: Response contains no data - isRecycled: 0
Thu Sep 10 08:56:36 2009 <1899912525369961> *******Exception type [HALF_OPEN_SOCKET_RETRY] (Unexpected EOF reading HTTP status - request retry) raised at line 854 of ../nsapi/URL.cpp
Thu Sep 10 08:56:36 2009 <1899912525369961> initJVMID: Failed to retrieved JVMID for 172.23.4.53:8001:8001
Thu Sep 10 08:56:36 2009 <1899912525369961> initJVMID: Marked server as BAD
如果请求处理成功,将会看到类似于以下的信息:
Thu Sep 10 08:56:36 2009 <1899912525369961> ServerInfo struct for JVMID '-977705075' populated
Server Details are:
OrigHostInfo [172.23.4.52]
isOrigHostInfoDNS [0]
Host [172.23.4.52]
Port [8001]
SecurePort [8201]
Thu Sep 10 08:56:36 2009 <1899912525369961> Initializing lastIndex=0 for a list of length=1
initJVMID()除了更新jvmID,同时还给我们这个请求分配了preferred server list。
获取到请求的preferred后,程序的控制权将回到proxy.wl_proxy(),这个方法是所有http请求的入口。回到wl_proxy后,进入while循环,循环的终止条件就是我们的retry次数(默认5次)。进入循环后,debug信息如下:
Thu Sep 10 08:56:36 2009 <1899912525369961> attempt #0 out of a max of 5
plugin要成功发送一个http请求,首先需要拿到connection,如果我们设置了keep-alive,首先会从connection pool中获取,如果没有,则创建新的物理连接。debug信息分别如下:
Wed Sep 02 14:35:45 2009 <553612518733456> got a pooled connection to preferred server '172.23.4.53/8001for '/test_sleep/testsleep.jsp', Local port:3651
Wed Sep 02 14:33:12 2009 <553612518731924> created a new connection to preferred server '172.23.4.53/8001' for '/test_sleep/testsleep.jsp', Local port:3636
拿到connection后,plugin会将request的header信息发送到server端,并从连接上读取response。此时上面两种连接都可能出现HALF_OPEN_SOCKET_RETRY。我们分别看看这两种情况:
1:如果pool connection对应的后端服务器已经被shutdown,那么我们那pool connection做操作的时候,肯定无法完成,因此很容易碰到HALF_OPEN_SOCKET_RETRY。碰到HALF_OPEN_SOCKET_RETRY,plugin会做retry,而不是直接failover。重新去getConnection,如果pool中corrupted connection足够多,那么五次失败后,客户端最终会看到“No backend server available”,debug中会有如下信息:
Tue Sep 1 10:43:41 2009 <10088125176582121> request [/socs/favicon.ico] did NOT process successfully..................
2:pool中的connection不是很多,比如2个,那么我们做完两次retry后,这是就要创建物理的连接,如果连接创建失败,这个server会立刻mark bad,请求将被failover到secondary,debug信息如下:
Wed Sep 02 14:36:06 2009 <553612518733456> *******Exception type [CONNECTION_REFUSED] (Error connecting to host 10.182.216.198:8002) raised at line 1732 of ../nsapi/URL.cpp
如果创建连接成功,但sendRequestHeader的时候发生HALF_OPEN_SOCKET_RETRY,那么plugin同样会继续作retry,而不是failover。如果剩余几次retry结果都一样(创建连接成功,但sendRequestHeader失败),客户最终也会看到“No backend server available。日志通常如下:
Tue Sep 1 10:43:41 2009 <10088125176582121> attempt #5 out of a max of 5
Tue Sep 1 10:43:41 2009 <10088125176582121> created a new connection to preferred server '172.23.4.52/8001' for '/socs/favicon.ico', Local port:49416
......
Tue Sep 1 10:43:41 2009 <10088125176582121> URL::sendHeaders(): meth='GET' file='/socs/favicon.ico' protocol='HTTP/1.1'
......
Tue Sep 1 10:43:41 2009 <10088125176582121> readStatus: Local port of the socket 49416, connected to Remote Host/Port 172.23.4.52/8001
Tue Sep 1 10:43:41 2009 <10088125176582121> readStatus: Response contains no data - isRecycled: 0
Tue Sep 1 10:43:41 2009 <10088125176582121> *******Exception type [HALF_OPEN_SOCKET_RETRY] (Unexpected EOF reading HTTP status - request retry) raised at line 854 of ../nsapi/URL.cpp
Tue Sep 1 10:43:41 2009 <10088125176582121> got exception in sendRequest phase: HALF_OPEN_SOCKET_RETRY: [os error=0, line 854 of ../nsapi/URL.cpp]: Unexpected EOF reading HTTP status - request retry at line 3080
对于1,这个可以理解,如果pool中connection被关闭(keep-alive超时)完了,客户就不会碰到这样的问题问题了。而对于2,更多的应该说是OS的问题,OS没有正确释放端口。如果端口释放成功,plugin做url.connect()的时候,应该是收到connection refuse,而不是正常创建连接(实际上是无用连接,使用时出现Socket_Half_Open)。对于2,我们可以通过以下的方法检查:
1:ps -ef | grep java,检查对应的managed server时候shutdown
2:netstat -a | grep listening port,如果server已经shutdown了,却还能看到listening port,那么就是OS的问题了。
写了这么多,觉得比较繁琐,不知道大家能否看得明白,建议最好拿一个wl_proxy的debug log,对照着看。
posted on 2009-09-14 08:54
走走停停又三年 阅读(6621)
评论(5) 编辑 收藏 所属分类:
Weblogic