clevengr
commented
3 years ago Initial investigation showed that the socket timeout on the event feed socket is set to 130 seconds (in method RemoteContestAPIAdapter.connect()). This should mean that the event feed socket won't time out for a little over 2 minutes (whereas the above logs indicate a timeout is happening after around 10 seconds).
On further review, it appears that the SocketTimeoutException may not actually be coming from the event feed socket at all. The line of code referenced above,
files = remoteContestAPIAdapter.getRemoteSubmissionFiles("" + overrideSubmissionID);in the RemoteEventFeedMonitor class calls getRemoteSubmissionFiles(String submissionID) in the RemoteContestAPIAdapter class. This in turn calls getRemoteSubmissionFiles(URL), which calls createConnection(url) to create a NEW connection -- not to the event feed, but rather to the /submissions/<submissionID>/files endpoint of the remote CCS API.
createConnection() in turn calls pc2.util.HTTPSSecurity.createConnection() to create this new connection -- and the last statement therein is
conn.setConnectTimeout(10000);So the connection to the remote CCS
After creating the connection, method getRemoteSubmissionFiles(url) call conn.getInputStream(), whose javadoc says:
Returns an input stream that reads from this open connection.A SocketTimeoutException can be thrown when reading from the returned input stream if the read timeout expires before data is available for read.This seems like the likely source of the SocketTimeoutException which is causing submissions to be lost. Recommend increasing this timeout.
Describe the issue:
The PC2 Shadow occasionally loses submissions which come from the remote CCS, which in turn sometimes causes failures in matching the scoreboards. (The reason it only sometimes causes scoreboard failures is that a lost submission for a problem might not be a submission that affects scoring.)
It appears that the loss of submissions may be related to the shadow throwing an exception when attempting to pull the FILES associated with the submission from the remote CCS. Specifically, I ran a shadow against a rerun of the NAC21 contest and, after detailed analysis, determined that the shadow received a notice from Kattis that there existed a submission with id 7519100, but no such submission was entered into PC2. The relevant log messages are given below; the complete log is attached below.
(Note: submission 7519100 is just one example; there were also other submissions lost in my test.)
Note that the log shows an exception was thrown immediately after the message "Fetching files from remote system". The exception message is "Exception parsing event...", but that is a bogus message (corrected in PR #284); the exception actually occurs while processing the "submission" event, not while parsing it.
Specifically, the exception appears to happen on the following line in the RemoteEventFeedMonitor:
MOST of the time this works fine (i.e., returns the files from the remote system corresponding to the specified submissionID). However, ONCE IN A WHILE it throws "SocketTimeoutException". (Specifically, for the test I ran it lost 4 submissions out of 737; see the attached file: NAC21.Rerun.8.19.21.LostSubmissions.txt .)
The log NAC21.Rerun.8.19.21.FEEDER1@site1-0.log shows two interesting facts:
dumpPacketlog messages.These may indicate that the socket timeout just isn't set to be long enough, and the extensive logging which is done by
dumppacketis causing the socket to time out.To Reproduce: There doesn't seem to be any guaranteed way to reproduce this; it is timing-dependent. However, in three NAC runs, submissions were lost in all three runs, so it seems like it's likely to happen just by following the steps listed in PR #284.
Environment in which this was detected: A shadow running in Eclipse under Windows 10 and java 1.8_201, with a server running on the AWS pc2 server, an Admin running on the AWS "System2" machine, and AutoJudges running on the AWS Judge1-Judge5 machines.
Possible solutions:
dumpPacketcalls which are generating large amounts of logging and at the same time stopping other code from executing (the RemoteEventFeedMonitor is probably blocked on accessing the remote event feed while it's waiting for logging to complete...)