LLRnet/PRPnet rally August 12th-19th

[gd_barnes]

Just to clarifly: It was likely the attempt to get into the machine through VNC that caused the reboot. It apparently was not a random event. Since we know what caused that, that particular issue should hopefully not happen again.

[rogue]

Originally Posted by gd_barnes

I just now stopped and restarted the server. It now seems to be handing out and accepting pairs again,

I'll keep an eye on it. Max, if you can help with that as you have time, that would help also. Do you know why there would be a maximum # of connections?

Edit: I just did one more thing to prevent a problem that we had with the last rally: I renamed the prpserver.log file to prpserver-0813.log. It was already at 755 MB. I'll keep doing that at least once/day. Something about its size caused the server to have problems last time.

Is there any explanation as to why prpserver.log is so large? I assume that debuglevel is set to 0 in the prpserver.ini file. Has anyone looked at it to see if there is anything unusual in that file? The file might contain information to reveal why max connections was reached. The last time I had seen this it appeared to be related to a user who had a .sh file (or .bat file) that got stuck in a loop trying to start the client. I never found out which version of the client they were running or what their script looked like to determine if the problem was truly with their .sh/.bat file or with the client.

You can set the max size of the log file in prpserver.ini. When it reaches that size it will rename it to prpserver.log.old (after deleting the previous prpserver.log.old file).

[mdettweiler]

Originally Posted by rogue

Is there any explanation as to why prpserver.log is so large? I assume that debuglevel is set to 0 in the prpserver.ini file. Has anyone looked at it to see if there is anything unusual in that file? The file might contain information to reveal why max connections was reached. The last time I had seen this it appeared to be related to a user who had a .sh file (or .bat file) that got stuck in a loop trying to start the client. I never found out which version of the client they were running or what their script looked like to determine if the problem was truly with their .sh/.bat file or with the client.

You can set the max size of the log file in prpserver.ini. When it reaches that size it will rename it to prpserver.log.old (after deleting the previous prpserver.log.old file).

I have debuglevel set to 1 on all the servers--there have been way too many times that we ran into a one-off server bug that is nearly impossible to reproduce, so I like to have all the debug information available for sure. It produces some very big log files, but by renaming them to prpserver-MMDD.log periodically and compressing them with lzma, I can store them pretty efficiently.

I should implement the max log file size feature as you suggest and set it to 500MB or so. I'll still try to rename them periodically anyway to prevent any content from being deleted, but that should at least provide a failsafe in case I forget. Also, something I've been meaning to do for a while but haven't yet gotten the chance is to write a script that automatically renames the logs and moves them to a log/ folder within the server directory--that would completely obviate the need for manual renaming.

As far as this specific instance, I remember last time something like this happened the log file wasn't much help; still, I'll give it a look and see if I can come up with anything useful.

[vaughan]

Where's MyDogBuster? With the rally running now his #2 rank is looking shaky.

Question for the mods: Would it help reduce the load on the server if we cached more than 5 tasks?

[mdettweiler]

Originally Posted by vaughan

Question for the mods: Would it help reduce the load on the server if we cached more than 5 tasks?

No, it's not the server load that's the problem, rather that I dropped the ball and forgot to clean out the logfile as often as I should. For the duration of the rally Gary's going to be moving it out twice a day, which should be more than plenty (I'd even be fine with once/day); we'd surely be fine even if everyone ran with a cache size of 1.

Also, note that this only applies to PRPnet port 9000. LLRnet (which is where I see your cores are) generates the same load on the server no matter what your cache size is; it is more accurately described as a queue system opearating on a FIFO (first in, first out) model, with each pair being returned as soon as it completes and a new one being added to the end of the queue at that time. So no matter what the queue size, it communicates with the server just as often.

[mdettweiler]

I think I just figured out why the server got stuck in that "too many connections" issue earlier--and it didn't have anything to do with the size of the log file. I just realized that I had entirely forgotten to specify the maxclients= line in prpserver.ini! The maxclients feature was introduced in v3.3.0, but I didn't make any changes to any of the servers' .ini files when I upgraded them from 3.2.5--hence, maxclients= was unspecified and it used the default value of 10.

10 concurrent connections is far from impossible during a heavy-load period like this--and indeed it looks like it did happen:

[2010-08-13 12:09:56 CDT] 7: client connecting from 91.149.36.77
[2010-08-13 12:09:57 CDT] 4: client connecting from 91.149.36.77
[2010-08-13 12:10:05 CDT] 6: client connecting from 77.21.236.127
[2010-08-13 12:10:07 CDT] 8: client connecting from 91.149.36.77
[2010-08-13 12:10:15 CDT] 9: client connecting from 77.21.236.127
[2010-08-13 12:10:17 CDT] 10: client connecting from 91.149.36.77
[2010-08-13 12:10:19 CDT] 11: client connecting from 91.149.36.77
[2010-08-13 12:10:27 CDT] 12: client connecting from 91.149.36.77
[2010-08-13 12:10:27 CDT] 13: client connecting from 91.149.36.77
[2010-08-13 12:10:28 CDT] 14: client connecting from 91.149.36.77
[2010-08-13 12:10:28 CDT] 14: sending [ERROR:  Server cannot handle more connections]
[2010-08-13 12:10:28 CDT] Server has reached max connections of 10.  Connection from 91.149.36.77 rejected
[2010-08-13 12:10:28 CDT] 14: closing socket
[2010-08-13 12:10:30 CDT] 14: client connecting from 91.149.36.77
[2010-08-13 12:10:30 CDT] 14: sending [ERROR:  Server cannot handle more connections]
[2010-08-13 12:10:30 CDT] Server has reached max connections of 10.  Connection from 91.149.36.77 rejected
[2010-08-13 12:10:30 CDT] 14: closing socket
[2010-08-13 12:10:30 CDT] 14: client connecting from 91.149.36.77
[2010-08-13 12:10:30 CDT] 14: sending [ERROR:  Server cannot handle more connections]
[2010-08-13 12:10:30 CDT] Server has reached max connections of 10.  Connection from 91.149.36.77 rejected
[2010-08-13 12:10:30 CDT] 14: closing socket

What should have happened was for the server to just reject the 10th client (in this case, socket #14), and continue communicating with the others--and then once those finished and disconnected, sockets would be freed up and it would again accept communication on them. However, what actually happened was that the server got stuck in rejecting communications on socket #14--apparently dropping the others (#7, 4, 6, 8, 9, 10, 11, 12, and 13) and having no further communication with them. From that point they remained perpetually open, and any new clients got the unlucky socket #14 which of course is the 10th socket to be opened, thus they were turned away.

Mark, this looks like a bug--any idea why it's doing this?

@all: meanwhile, I've set the server's log file limit to 500 MB as previously discussed. It looks like it's not needed after all, but it shouldn't hurt. Also, I've set maxclients=1000, so we shouldn't run into any more of the above problem unless somebody's client really does go bonkers and get in some kind of loop.

[gd_barnes]

Good work Max.

On the logfile, I'm about ready to do my semi-daily renaming. One thing about your 500 MB limit: That won't help if that turns out to be an issue. It had reached 778 MB in right around a day after the rally started. [Or perhaps the logfile included a lot of logging from long before the rally started. I hadn't checked that.] Regardless, the twice daily renaming won't hurt.

[AMDave]

have a look at:
$man 8 logrotate

Max should have the server doing that for you in a jiffy

[rogue]

Originally Posted by mdettweiler

Mark, this looks like a bug--any idea why it's doing this?

My best guess is that some sort of deadlock is occurring and the server isn't handling it correctly. Being a multi-threaded application, the server needs to lock certain resources so that only one thread can access them at a time. It is possible that two threads are deadlocking. IIRC, pthreads will tell you when a deadlock has occurred. Since I don't check for return codes from some pthread calls, it is possible that I'm not handing an error that needs to be handled. I need to investigate further.

[mdettweiler]

Originally Posted by gd_barnes

Good work Max.

On the logfile, I'm about ready to do my semi-daily renaming. One thing about your 500 MB limit: That won't help if that turns out to be an issue. It had reached 778 MB in right around a day after the rally started. [Or perhaps the logfile included a lot of logging from long before the rally started. I hadn't checked that.] Regardless, the twice daily renaming won't hurt.

Yes, that did include over a month of earlier logging IIRC.

Originally Posted by AMDave

have a look at:
$man 8 logrotate

Max should have the server doing that for you in a jiffy

Thanks, I'll check it out.

[Vato]

I'm a couple of days late (due to work) but I'm in the rally now!