<div class="gmail_quote">On Tue, Apr 23, 2013 at 10:08 AM, Lech Nieroda <span dir="ltr">&lt;<a href="mailto:nieroda.lech@uni-koeln.de" target="_blank">nieroda.lech@uni-koeln.de</a>&gt;</span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
Dear list,<br>
<br>
we have encountered a problem with our torque 4.1.4/maui 3.3.1<br>
scheduling system. It seems to be a bug within pbs_server, where under<br>
certain conditions a socket isn&#39;t closed properly.<br>
<br>
The symptoms:<br>
- the server stops writing to the log and stops responding to commands.<br>
The only way to restart it is &#39;kill -9&#39;<br>
- thousands of CLOSE_WAIT connections accumulate in a short period of<br>
time (we&#39;ve had ca 20k of those)<br>
- clients log error messages like &quot;LOG_ERROR::read_tcp_reply,<br>
Mismatching protocols. Expected protocol 4 but read reply for 0&quot;<br>
<br>
Workaround:<br>
- a restart of the server removes all CLOSE_WAIT connections. Once<br>
restarted, the server writes to the log again but remains unresponsive.<br>
The clients still log the &quot;mismatching protocols&quot; messages<br>
- after the server restart, all pbs_moms are restarted (again, only a<br>
&#39;kill -9&#39; is able to stop the pbs_moms)<br>
<br>
Afterwards, the system is operational again.<br>
<br>
Here are some logs:<br>
<br>
&#39;netstat -nap&#39; snippet on the server side:<br>
[snip]<br>
tcp      461      0 <a href="http://172.18.0.197:15001" target="_blank">172.18.0.197:15001</a>          <a href="http://172.18.1.167:422" target="_blank">172.18.1.167:422</a><br>
     CLOSE_WAIT  11478/pbs_server<br>
tcp      417      0 <a href="http://172.18.0.197:15001" target="_blank">172.18.0.197:15001</a>          <a href="http://172.18.1.101:356" target="_blank">172.18.1.101:356</a><br>
     CLOSE_WAIT  11478/pbs_server<br>
tcp      413      0 <a href="http://172.18.0.197:15001" target="_blank">172.18.0.197:15001</a>          <a href="http://172.18.4.60:312" target="_blank">172.18.4.60:312</a><br>
     CLOSE_WAIT  11478/pbs_server<br>
tcp      380      0 <a href="http://172.18.0.197:15001" target="_blank">172.18.0.197:15001</a>          <a href="http://172.18.4.142:394" target="_blank">172.18.4.142:394</a><br>
     CLOSE_WAIT  11478/pbs_server<br>
tcp      440      0 <a href="http://172.18.0.197:15001" target="_blank">172.18.0.197:15001</a>          <a href="http://172.18.3.13:270" target="_blank">172.18.3.13:270</a><br>
     CLOSE_WAIT  11478/pbs_server<br>
tcp      417      0 <a href="http://172.18.0.197:15001" target="_blank">172.18.0.197:15001</a>          <a href="http://172.18.2.124:382" target="_blank">172.18.2.124:382</a><br>
     CLOSE_WAIT  11478/pbs_server<br>
tcp      415      0 <a href="http://172.18.0.197:15001" target="_blank">172.18.0.197:15001</a>          <a href="http://172.18.4.138:398" target="_blank">172.18.4.138:398</a><br>
     CLOSE_WAIT  11478/pbs_server<br>
tcp        1      0 <a href="http://172.18.0.197:15001" target="_blank">172.18.0.197:15001</a>          <a href="http://172.18.0.194:52162" target="_blank">172.18.0.194:52162</a><br>
     CLOSE_WAIT  11478/pbs_server<br>
tcp        1      0 <a href="http://172.18.0.197:15001" target="_blank">172.18.0.197:15001</a>          <a href="http://172.18.6.14:51976" target="_blank">172.18.6.14:51976</a><br>
     CLOSE_WAIT  11478/pbs_server<br>
[snap]<br>
<br>
last server messages:<br>
[snip]<br>
04/21/2013 11:38:03;0004;PBS_Server.11481;Svr;svr_is_request;message<br>
received from addr <a href="http://172.18.2.72:405" target="_blank">172.18.2.72:405</a>: mom_port 15002  - rm_port 15003<br>
04/21/2013 11:38:03;0004;PBS_Server.11481;Svr;svr_is_request;message<br>
STATUS (4) received from mom on host cheops40218 (<a href="http://172.18.2.72:405" target="_blank">172.18.2.72:405</a>) (sock 12)<br>
04/21/2013 11:38:03;0004;PBS_Server.11481;Svr;svr_is_request;IS_STATUS<br>
received from cheops40218<br>
04/21/2013 11:38:03;0040;PBS_Server.11481;Req;is_stat_get;received<br>
status from node cheops40218<br>
04/21/2013<br>
11:38:03;0040;PBS_Server.11481;Req;update_node_state;adjusting state for<br>
node cheops40218 - state=0, newstate=0<br>
04/21/2013 11:38:03;0004;PBS_Server.11525;Svr;svr_is_request;message<br>
received from addr <a href="http://172.18.2.67:921" target="_blank">172.18.2.67:921</a>: mom_port 15002  - rm_port 15003<br>
04/21/2013 11:38:03;0004;PBS_Server.11525;Svr;svr_is_request;message<br>
STATUS (4) received from mom on host cheops40213 (<a href="http://172.18.2.67:921" target="_blank">172.18.2.67:921</a>) (sock 13)<br>
04/21/2013 11:38:03;0004;PBS_Server.11525;Svr;svr_is_request;IS_STATUS<br>
received from cheops40213<br>
04/21/2013 11:38:03;0040;PBS_Server.11525;Req;is_stat_get;received<br>
status from node cheops40213<br>
04/21/2013<br>
11:38:03;0040;PBS_Server.11525;Req;update_node_state;adjusting state for<br>
node cheops40213 - state=0, newstate=0<br>
04/21/2013 11:38:11;0100;PBS_Server.11605;Req;;Type StatusJob request<br>
received from root@cheops10, sock=11<br>
[snap]<br>
<br>
<br>
netstat on the client side (show ESTABLISHED or SYN_SENT on port 15001):<br>
[snip]<br>
cheops21410: tcp        0    375 <a href="http://172.18.4.128:890" target="_blank">172.18.4.128:890</a><br>
<a href="http://172.18.0.197:15001" target="_blank">172.18.0.197:15001</a>          ESTABLISHED 8676/pbs_mom<br>
7[snap]<br>
<br>
[snip]<br>
cheops41511: tcp        0      1 <a href="http://172.18.5.165:716" target="_blank">172.18.5.165:716</a><br>
<a href="http://172.18.0.197:15001" target="_blank">172.18.0.197:15001</a>          SYN_SENT    9602/pbs_mom<br>
[snap]<br>
<br>
client messages:<br>
[snip]<br>
Apr 21 11:43:25 s_sys@cheops21410 pbs_mom: LOG_ERROR::read_tcp_reply,<br>
Mismatching protocols. Expected protocol 4 but read reply for 0<br>
Apr 21 11:43:25 s_sys@cheops21410 pbs_mom: LOG_ERROR::read_tcp_reply,<br>
Could not read reply for protocol 4 command 4: End of File<br>
Apr 21 11:43:25 s_sys@cheops21410 pbs_mom:<br>
LOG_ERROR::mom_server_update_stat, Couldn&#39;t read a reply from the server<br>
Apr 21 11:43:25 s_sys@cheops21410 pbs_mom:<br>
LOG_ERROR::mom_server_all_update_stat, Could not contact any of the<br>
servers to send an update<br>
[snap]<br>
<br>
Is this a server bug?<br>
<br>
Regards,<br>
Lech Nieroda<br>
--<br>
Dipl.-Wirt.-Inf. Lech Nieroda<br>
Regionales Rechenzentrum der Universität zu Köln (RRZK)<br>
Universität zu Köln<br>
Weyertal 121<br>
Raum 309 (3. Etage)<br>
D-50931 Köln<br>
Deutschland<br>
<br>
Tel.: <a href="tel:%2B49%20%28221%29%20470-89606" value="+4922147089606">+49 (221) 470-89606</a><br>
E-Mail: <a href="mailto:nieroda.lech@uni-koeln.de">nieroda.lech@uni-koeln.de</a><br>
<br>
<br>
_______________________________________________<br>
torqueusers mailing list<br>
<a href="mailto:torqueusers@supercluster.org">torqueusers@supercluster.org</a><br>
<a href="http://www.supercluster.org/mailman/listinfo/torqueusers" target="_blank">http://www.supercluster.org/mailman/listinfo/torqueusers</a><br>
</blockquote></div><br>Lech,<br><br>Have you been able to reproduce the condition on demand?<br clear="all"><br>-- <br>Ken Nielson<br>+1 801.717.3700 office +1 801.717.3738 fax<br>1712 S. East Bay Blvd, Suite 300  Provo, UT  84606<br>
<a href="http://www.adaptivecomputing.com" target="_blank">www.adaptivecomputing.com</a><br><br>