posts - 42,comments - 83,trackbacks - 0
        目前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

FeedBack:
# re: Weblogic Apache Plugin由HALF_OPEN_SOCKET_RETRY引起的“No backend server available”
2009-09-14 21:16 | sorcerer
一直没搞明白,apache如何进行心跳检测?后端的appServer主动报告?hung的情况可以被识别为not available吗?  回复  更多评论
  
# re: Weblogic Apache Plugin由HALF_OPEN_SOCKET_RETRY引起的“No backend server available”
2009-09-15 08:55 | 走走停停又三年
对于无法连接的server,apache会做mark bad。过了max skip time后,这个server会被重新加入server list(无论这个server是否存活),然后尝试创建到该server的连接,如果失败,那么继续将其mark bad。至于,hanging server的问题,参考WLIOTimeoutSecs。  回复  更多评论
  
# re: Weblogic Apache Plugin由HALF_OPEN_SOCKET_RETRY引起的“No backend server available”
2009-09-15 22:05 | sorcerer
搜索WLIOTimeoutSecs居然可以搜到本帖了....
既然Apache + Weblogic Cluster可以做load balance和failover那么是不是不需要lvs了?  回复  更多评论
  
# re: Weblogic Apache Plugin由HALF_OPEN_SOCKET_RETRY引起的“No backend server available”
2009-09-15 22:11 | 走走停停又三年
@sorcerer

你可以这么认为,如果费用不吃紧可以考虑lvs。failover是由weblogic的session replication实现的,这个是硬件层面无法做到的。  回复  更多评论
  
# re: Weblogic Apache Plugin由HALF_OPEN_SOCKET_RETRY引起的“No backend server available”
2009-09-15 23:32 | sorcerer
还是有点迷惑,我们用了f5,session replication没做,怕影响性能,但是系统都是sso的,应该也不用重登录.那么f5的主要功能似乎就是load balance了,apache既然可以做了,干嘛还要花这个钱呢.难道,只是因为厂商吹嘘的硬件更稳定,性能更高?当然配置起来确实方便.  回复  更多评论
  

只有注册用户登录后才能发表评论。


网站导航: