PRPnet server bugs and barfing problem

[mdettweiler]

Originally Posted by rogue

I believe that a kill -6 will create a core dump when it kills the process. I suggest you read the documentation for your OS or use "man kill" from the command prompt to see if it tells you.

Okay, I'll try that next time. Reviewing the "man kill" documentation, I see that -6 is SIGABRT, rather than -9/SIGKILL which I'd been using before. Presumably they behave the same except that -6 will produce a core dump.

[gd_barnes]

Mark and Max,

Let's think out of the box for a moment:

What you are trying to do is debug a program by turning on debugging software that will run against a program that may or may not ever show the same problem again.

Aren't we doing this a little bit backwards? Shouldn't we figure out what happened to the data and then look at the program? Right now, it appears that we are looking at the program first and trying to figure out what it is doing wrong.

Ian asked for Max to look at log files and tell him what happened to the error tests that Lennart returned.

The log that Max posted is very good for debugging this problem. It shows a test(s) being rejected. What we need to know is where is that test now, was it in the original file loaded, and what happened from the time Lennart got it (if he ever got it) to the time it was rejected?

We seem to keep going around and around with the same types of issues and almost "guessing" where the problem is in the program and not hitting the nail on the head a majority of the time when we make related changes.

Testing a server is difficult in that you cannot simulate the same problem time and time again. So I think we need to find where the problem data is or where it got lost and then trace back from there.


Thank you,
Gary

[mdettweiler]

All right, I looked through the completed_tests.log file and found some rather interesting stuff about one of the "not on server" k/n pairs in the log excerpt I posted above, 51255*6^144850+1. I'm posting this from my computer, so I can't copy and paste the logfile directly from the server; I'll edit this post in a minute from the server machine to include the respective log excerpts for this.

Edit: Okay, here's the completed_tests.log from the situation in question:

[2009-08-11 13:17:39 GMT] 125098*6^144812+1:  Email: sm5ymt@pekhult.se  User: sm5ymt  Client: _6 Program: pfgw  Residue: 885DFA5A9DA38437  
[2009-08-11 13:18:16 GMT] 127688*6^144812+1:  Email: sm5ymt@pekhult.se  User: sm5ymt  Client: _6 Program: pfgw  Residue: 1178C626786D82DD  
[2009-08-11 13:25:32 GMT] 172257*6^144854+1:  Email: sm5ymt@pekhult.se  User: sm5ymt  Client: _6 Program: pfgw  Residue: DC3BFF4C22A877B2  
[2009-08-11 13:26:14 GMT] 51255*6^144850+1:  Email: sm5ymt@pekhult.se  User: sm5ymt  Client: _6 Program:   Residue:   
[2009-08-11 13:27:47 GMT] 74612*6^144857+1:  Email: sm5ymt@pekhult.se  User: sm5ymt  Client: _6 Program:   Residue:   
[2009-08-11 13:29:20 GMT] 172257*6^144862+1:  Email: sm5ymt@pekhult.se  User: sm5ymt  Client: _6 Program:   Residue:   
[2009-08-11 13:30:53 GMT] 51255*6^144850+1:  Email: sm5ymt@pekhult.se  User: sm5ymt  Client: _6 Program:   Residue:   
[2009-08-11 13:32:26 GMT] 166753*6^144821+1:  Email: gbarnes017@gmail.com  User: gd_barnes  Client: humpford Program:   Residue:   
[2009-08-11 13:33:59 GMT] 113966*6^144847+1:  Email: gbarnes017@gmail.com  User: gd_barnes  Client: humpford Program:   Residue:   
[2009-08-11 13:35:32 GMT] 166753*6^144821+1:  Email: gbarnes017@gmail.com  User: gd_barnes  Client: humpford Program:   Residue:   
[2009-08-11 14:49:53 GMT] 166753*6^144821+1:  Email: gbarnes017@gmail.com  User: gd_barnes  Client: humpford Program: pfgw  Residue: 10AC14C3AE34D549  
[2009-08-11 14:49:53 GMT] 33706*6^144822+1:  Email: gbarnes017@gmail.com  User: gd_barnes  Client: humpford Program: pfgw  Residue: 4E36BDFF51502C8C  
[2009-08-11 14:49:53 GMT] 124221*6^144823+1:  Email: gbarnes017@gmail.com  User: gd_barnes  Client: humpford Program: pfgw  Residue: D0351CD9238CE1EE  
[2009-08-11 14:49:53 GMT] 113966*6^144847+1:  Email: gbarnes017@gmail.com  User: gd_barnes  Client: humpford Program: pfgw  Residue: D4CABC0C6CB05A72  
[2009-08-11 14:49:53 GMT] 51255*6^144848+1:  Email: gbarnes017@gmail.com  User: gd_barnes  Client: humpford Program: pfgw  Residue: 1FE4C07A9EC5EC8B  
[2009-08-11 14:49:53 GMT] 112783*6^144849+1:  Email: gbarnes017@gmail.com  User: gd_barnes  Client: humpford Program: pfgw  Residue: 7978E61C19BBE028

Other than a handful of barfed tests, the main thing that's remarkable about this example is that the particular test in question had a (blank) result accepted TWICE in short succession. It would seem that somewhere along the line, the server is neglecting to consider that that test has already been accepted--either that, or it realized that it wasn't valid since it didn't have a residual, but logged it in completed_tests.log anyway. (FYI: this is the last occurrence of that test in the file, so it seems that it didn't log it yet another time after that.)

Now let's examine debug.log from the same time frame:

[2009-08-11 13:25:40 GMT] Message coming on socket 5
[2009-08-11 13:25:40 GMT] socket 5 <<<< FROM sm5ymt@pekhult.se _6 sm5ymt
[2009-08-11 13:25:40 GMT] sm5ymt@pekhult.se connecting from 91.149.43.243
[2009-08-11 13:25:40 GMT] socket 5 <<<< RETURNWORK 2.2.4
[2009-08-11 13:25:40 GMT] socket 5 <<<< WorkUnit: 51255*6^144850+1 1249996661
[2009-08-11 13:25:40 GMT] socket 5 >>>> INFO: Workunit found
[2009-08-11 13:25:40 GMT] socket 5 <<<< End of Message
[2009-08-11 13:25:43 GMT] socket 5 <<<< QUIT
[2009-08-11 13:26:14 GMT] socket 5 (nothing received) 
[2009-08-11 13:26:14 GMT] socket 5 >>>> ERROR:  Test for 51255*6^144850+1 rejected.  No residue reported
[2009-08-11 13:26:14 GMT] sm5ymt@pekhult.se (_6) at 91.149.43.243: Rejected test on 51255*6^144850+1 due to no residue
[2009-08-11 13:26:14 GMT] socket 5 >>>> INFO: Test for candidate 51255*6^144850+1 accepted
[2009-08-11 13:26:14 GMT] 51255*6^144850+1: Test received by sm5ymt@pekhult.se at 91.149.43.243  Residue Residue: 
[2009-08-11 13:26:14 GMT] socket 5 >>>> End of Workunit Message
[2009-08-11 13:26:45 GMT] socket 5 (nothing received) 
[2009-08-11 13:26:45 GMT] socket 5 >>>> INFO: All 1 test results were accepted
[2009-08-11 13:26:45 GMT] Error sending <<INFO: All 1 test results were accepted>> to localhost:3000
[2009-08-11 13:26:45 GMT] socket 5 >>>> !!! send error !!!
[2009-08-11 13:26:45 GMT] socket 5 >>>> End of Message
[2009-08-11 13:26:45 GMT] Error sending <<End of Message>> to localhost:3000
[2009-08-11 13:26:45 GMT] socket 5 >>>> !!! send error !!!
[2009-08-11 13:27:16 GMT] socket 5 (nothing received) 
[2009-08-11 13:27:16 GMT] closing socket 5
<Snipped a bunch of other occurrences, most if not all of them with various "send error"'s, that weren't
relevant to the particular k/n pair we're tracking. I would have left them in, but the forum limits posts
to 10000 characters and it didn't fit otherwise.>
[2009-08-11 13:30:22 GMT] Message coming on socket 5
[2009-08-11 13:30:22 GMT] socket 5 <<<< FROM sm5ymt@pekhult.se _6 sm5ymt
[2009-08-11 13:30:22 GMT] sm5ymt@pekhult.se connecting from 91.149.43.243
[2009-08-11 13:30:22 GMT] socket 5 <<<< RETURNWORK 2.2.4
[2009-08-11 13:30:22 GMT] socket 5 <<<< WorkUnit: 51255*6^144850+1 1249996661
[2009-08-11 13:30:22 GMT] socket 5 >>>> INFO: Workunit found
[2009-08-11 13:30:22 GMT] socket 5 <<<< End of Message
[2009-08-11 13:30:22 GMT] socket 5 <<<< QUIT
[2009-08-11 13:30:53 GMT] socket 5 (nothing received) 
[2009-08-11 13:30:53 GMT] socket 5 >>>> ERROR:  Test for 51255*6^144850+1 rejected.  No residue reported
[2009-08-11 13:30:53 GMT] Error sending <<ERROR:  Test for 51255*6^144850+1 rejected.  No residue reported>> to localhost:3000
[2009-08-11 13:30:53 GMT] socket 5 >>>> !!! send error !!!
[2009-08-11 13:30:53 GMT] sm5ymt@pekhult.se (_6) at 91.149.43.243: Rejected test on 51255*6^144850+1 due to no residue
[2009-08-11 13:30:53 GMT] socket 5 >>>> INFO: Test for candidate 51255*6^144850+1 accepted
[2009-08-11 13:30:53 GMT] Error sending <<INFO: Test for candidate 51255*6^144850+1 accepted>> to localhost:3000
[2009-08-11 13:30:53 GMT] socket 5 >>>> !!! send error !!!
[2009-08-11 13:30:53 GMT] 51255*6^144850+1: Test received by sm5ymt@pekhult.se at 91.149.43.243  Residue Residue: 
[2009-08-11 13:30:53 GMT] socket 5 >>>> End of Workunit Message
[2009-08-11 13:30:53 GMT] Error sending <<End of Workunit Message>> to localhost:3000
[2009-08-11 13:30:53 GMT] socket 5 >>>> !!! send error !!!
[2009-08-11 13:31:24 GMT] socket 5 (nothing received) 
[2009-08-11 13:31:24 GMT] socket 5 >>>> INFO: All 1 test results were accepted
[2009-08-11 13:31:24 GMT] Error sending <<INFO: All 1 test results were accepted>> to localhost:3000
[2009-08-11 13:31:24 GMT] socket 5 >>>> !!! send error !!!
[2009-08-11 13:31:24 GMT] socket 5 >>>> End of Message
[2009-08-11 13:31:24 GMT] Error sending <<End of Message>> to localhost:3000
[2009-08-11 13:31:24 GMT] socket 5 >>>> !!! send error !!!
[2009-08-11 13:31:55 GMT] socket 5 (nothing received) 
[2009-08-11 13:31:55 GMT] closing socket 5

Ouch! It seems that the server is saying "result rejected" but then right after that saying "result accepted", with blank residual. And on top of that, the client isn't sticking around to hear any of it.

Anyway, it's 2 AM right now, so I need to get to bed. Hopefully this will be enough info to nail this down.

[gd_barnes]

Now we're talking. Let's keep hacking our way through every problem that we can find in the file. Let's make a list of each and every problem and put a status on the fix for that problem. If you'd like to make a posting in this thread, I could keep it up to date or simply create a completely separate thread called "PRPnet problem log and status".

In the programming industry on large projects, this is what we did. There had to be a huge master problem log along with their statuses. Frequently referring back to such a log showed a pattern of problems that pointed to a permanent long-term fix that corrected what would have been many future problems.


Gary

[rogue]

Originally Posted by gd_barnes

Mark and Max,

Let's think out of the box for a moment:

What you are trying to do is debug a program by turning on debugging software that will run against a program that may or may not ever show the same problem again.

Aren't we doing this a little bit backwards? Shouldn't we figure out what happened to the data and then look at the program? Right now, it appears that we are looking at the program first and trying to figure out what it is doing wrong.

Ian asked for Max to look at log files and tell him what happened to the error tests that Lennart returned.

The log that Max posted is very good for debugging this problem. It shows a test(s) being rejected. What we need to know is where is that test now, was it in the original file loaded, and what happened from the time Lennart got it (if he ever got it) to the time it was rejected?

We seem to keep going around and around with the same types of issues and almost "guessing" where the problem is in the program and not hitting the nail on the head a majority of the time when we make related changes.

Testing a server is difficult in that you cannot simulate the same problem time and time again. So I think we need to find where the problem data is or where it got lost and then trace back from there.

There is only so much I can glean from the posted information, even with debug turned on. I've looked through the code for problem spots. Some are easily found, others are much more elusive.

I have been a "one-man" team with writing the software. I can only dedicate so much time to it. If anyone would like to do a code review on the software and provide me feedback (via e-mail), I would appreciate it.

[rogue]

[2009-08-11 13:25:40 GMT] socket 5 <<<< RETURNWORK 2.2.4
[2009-08-11 13:25:40 GMT] socket 5 <<<< WorkUnit: 51255*6^144850+1 1249996661
[2009-08-11 13:25:40 GMT] socket 5 >>>> INFO: Workunit found
[2009-08-11 13:25:40 GMT] socket 5 <<<< End of Message
[2009-08-11 13:25:43 GMT] socket 5 <<<< QUIT
[2009-08-11 13:26:14 GMT] socket 5 (nothing received)

These lines make no sense. I don't see how the client could send messages like this. There should always be other things in the log between the "WorkUnit" and "End of Message" lines.

[mdettweiler]

Originally Posted by rogue

[2009-08-11 13:25:40 GMT] socket 5 <<<< RETURNWORK 2.2.4
[2009-08-11 13:25:40 GMT] socket 5 <<<< WorkUnit: 51255*6^144850+1 1249996661
[2009-08-11 13:25:40 GMT] socket 5 >>>> INFO: Workunit found
[2009-08-11 13:25:40 GMT] socket 5 <<<< End of Message
[2009-08-11 13:25:43 GMT] socket 5 <<<< QUIT
[2009-08-11 13:26:14 GMT] socket 5 (nothing received)

These lines make no sense. I don't see how the client could send messages like this. There should always be other things in the log between the "WorkUnit" and "End of Message" lines.

Yeah, those were confusing me too. Especially given the timestamps, it would appear that *something* is happening there (either that, or the client's just pausing for a while before sending its "QUIT").

Would it help if I put a client on the server (on my computer, which is running Windows) and had Visual Studio debugging it? If so, how would I do that?

[rogue]

Originally Posted by mdettweiler

Yeah, those were confusing me too. Especially given the timestamps, it would appear that *something* is happening there (either that, or the client's just pausing for a while before sending its "QUIT").

Would it help if I put a client on the server (on my computer, which is running Windows) and had Visual Studio debugging it? If so, how would I do that?

The QUIT is sent automatically when the client closes the socket. If you look at the ReturnWork and ReturnWorkUnit code in Work.cpp, it isn't clear how this could have happened. The code is relatively straight forward.

[mdettweiler]

I just got a real live barf on the client end from a client on my Windows box. Unfortunately I didn't have Visual Studio debugging it (since I wasn't expecting the client to be run; I had it strung up on the command line so that as soon as PFGW exited another run after finding a prime, it would go right to PRPnet and keep the machine busy), but I did get some good data on exactly how the Windows client behaves when this happens to it: I got a "prpclient.exe has encountered a problem and needs to close" error.

Here's the debug.log excerpt:

[2009-08-12 15:50:26 GMT] PRPNet Client application v2.2.4 started
[2009-08-12 15:50:26 GMT] User name mdettweiler at email address is max@noprimeleftbehind.net
[2009-08-12 15:50:26 GMT] in FindNextServerForWork: total time for client=0 seconds
[2009-08-12 15:50:26 GMT] suffix: PGpps-smalln, no work done yet, target pct work done=100
[2009-08-12 15:50:27 GMT] socket 1848 >>>> FROM max@noprimeleftbehind.net Core2Duo mdettweiler
[2009-08-12 15:50:27 GMT] PGpps-smalln: Getting work from server pgllr.mine.nu at port 10000
[2009-08-12 15:50:27 GMT] socket 1848 >>>> GETWORK 2.2.4 20
[2009-08-12 15:50:27 GMT] socket 1848 >>>> llr
[2009-08-12 15:50:27 GMT] socket 1848 >>>> phrot
[2009-08-12 15:50:27 GMT] socket 1848 >>>> pfgw
[2009-08-12 15:50:27 GMT] socket 1848 >>>> End of Message
[2009-08-12 15:50:30 GMT] socket 1848 <<<< ServerVersion: 2.2.4
[2009-08-12 15:50:31 GMT] socket 1848 <<<< ServerType: 3
<Snipped the lines where the server sent 20 WU's to the client. There was nothing anomalous in this part, and it made this post too long for the forum's 10000 character limit.>
[2009-08-12 15:50:31 GMT] socket 1848 <<<< End of Message
[2009-08-12 15:50:31 GMT] socket 1848 >>>> GETGREETING
[2009-08-12 15:50:31 GMT] socket 1848 <<<< PRPNet Server version 2.2.3
[2009-08-12 15:50:32 GMT] socket 1848 <<<< Hello Port 10k :)
[2009-08-12 15:50:32 GMT] socket 1848 <<<< OK.
[2009-08-12 15:50:32 GMT] socket 1848 >>>> QUIT
<Snipped the client's log entries from each test as it finished it; it was still too long for the forum even after snipping the above part.>
[2009-08-12 15:55:52 GMT] Total Time: 0:05:26 Total Tests: 20 Total PRPs Found: 0
[2009-08-12 15:55:52 GMT] socket 1844 >>>> FROM max@noprimeleftbehind.net Core2Duo mdettweiler
[2009-08-12 15:55:52 GMT] PGpps-smalln: Returning work to server pgllr.mine.nu at port 10000
[2009-08-12 15:55:52 GMT] socket 1844 >>>> RETURNWORK 2.2.4
[2009-08-12 15:55:52 GMT] socket 1844 >>>> WorkUnit: 9995*2^110239+1 1250092229
[2009-08-12 15:55:57 GMT] socket 1844 <<<< INFO: Workunit found
[2009-08-12 15:55:57 GMT] socket 1844 >>>> Test Result: cllr.exe 350F7F22C4AA3306
[2009-08-12 15:55:57 GMT] socket 1844 >>>> End of WorkUnit
[2009-08-12 15:55:57 GMT] socket 1844 <<<< INFO: Test for candidate 9995*2^110239+1 accepted
[2009-08-12 15:55:57 GMT] PGpps-smalln: INFO: Test for candidate 9995*2^110239+1 accepted
[2009-08-12 15:55:58 GMT] socket 1844 <<<< End of Workunit Message
[2009-08-12 15:55:58 GMT] socket 1844 >>>> WorkUnit: 7861*2^110240+1 1250092229
[2009-08-12 15:55:58 GMT] socket 1844 <<<< INFO: Workunit found
[2009-08-12 15:55:58 GMT] socket 1844 >>>> Test Result: cllr.exe 86C5FD3AE8F54E14
[2009-08-12 15:55:58 GMT] socket 1844 >>>> End of WorkUnit
[2009-08-12 15:55:59 GMT] socket 1844 <<<< INFO: Test for candidate 7861*2^110240+1 accepted
[2009-08-12 15:55:59 GMT] PGpps-smalln: INFO: Test for candidate 7861*2^110240+1 accepted
[2009-08-12 15:55:59 GMT] socket 1844 <<<< End of Workunit Message
[2009-08-12 15:55:59 GMT] socket 1844 >>>> WorkUnit: 9543*2^110240+1 1250092229
[2009-08-12 15:55:59 GMT] socket 1844 <<<< INFO: Workunit found
[2009-08-12 15:55:59 GMT] socket 1844 >>>> Test Result: cllr.exe EF0305A3AD119864
[2009-08-12 15:55:59 GMT] socket 1844 >>>> End of WorkUnit
[2009-08-12 15:56:00 GMT] socket 1844 <<<< INFO: Test for candidate 9543*2^110240+1 accepted
[2009-08-12 15:56:00 GMT] PGpps-smalln: INFO: Test for candidate 9543*2^110240+1 accepted
[2009-08-12 15:56:00 GMT] socket 1844 <<<< End of Workunit Message
[2009-08-12 15:56:00 GMT] socket 1844 >>>> WorkUnit: 1569*2^110241+1 1250092229
[2009-08-12 15:56:01 GMT] socket 1844 <<<< INFO: Workunit found
[2009-08-12 15:56:01 GMT] socket 1844 >>>> Test Result: cllr.exe 3EA23623BDB4B8F5
[2009-08-12 15:56:01 GMT] socket 1844 >>>> End of WorkUnit
[2009-08-12 15:56:02 GMT] socket 1844 <<<< INFO: Test for candidate 1569*2^110241+1 accepted
[2009-08-12 15:56:02 GMT] PGpps-smalln: INFO: Test for candidate 1569*2^110241+1 accepted
[2009-08-12 15:56:02 GMT] socket 1844 <<<< End of Workunit Message
[2009-08-12 15:56:02 GMT] socket 1844 >>>> WorkUnit: 8467*2^110240+1 1250092229
[2009-08-12 15:56:03 GMT] socket 1844 <<<< INFO: Workunit found
[2009-08-12 15:56:03 GMT] socket 1844 >>>> Test Result: cllr.exe 41373ADEAAE81265
[2009-08-12 15:56:03 GMT] socket 1844 >>>> End of WorkUnit
[2009-08-12 15:56:03 GMT] socket 1844 <<<< INFO: Test for candidate 8467*2^110240+1 accepted
[2009-08-12 15:56:03 GMT] PGpps-smalln: INFO: Test for candidate 8467*2^110240+1 accepted
[2009-08-12 15:56:04 GMT] socket 1844 <<<< End of Workunit Message
[2009-08-12 15:56:04 GMT] socket 1844 >>>> WorkUnit: 5637*2^110240+1 1250092229
[2009-08-12 15:56:04 GMT] socket 1844 <<<< INFO: Workunit found
[2009-08-12 15:56:04 GMT] socket 1844 >>>> Test Result: cllr.exe 9856B86C6517F0B6
[2009-08-12 15:56:04 GMT] socket 1844 >>>> End of WorkUnit
[2009-08-12 15:56:05 GMT] socket 1844 <<<< INFO: Test for candidate 5637*2^110240+1 accepted
[2009-08-12 15:56:05 GMT] PGpps-smalln: INFO: Test for candidate 5637*2^110240+1 accepted
[2009-08-12 15:56:05 GMT] socket 1844 <<<< End of Workunit Message
[2009-08-12 15:56:05 GMT] socket 1844 >>>> WorkUnit: 3341*2^110243+1 1250092229
[2009-08-12 15:56:05 GMT] socket 1844 <<<< INFO: Workunit found
[2009-08-12 15:56:05 GMT] socket 1844 >>>> Test Result: cllr.exe F00C2EA7CACA6CF4
[2009-08-12 15:56:05 GMT] socket 1844 >>>> End of WorkUnit
[2009-08-12 15:56:06 GMT] socket 1844 <<<< INFO: Test for candidate 3341*2^110243+1 accepted
[2009-08-12 15:56:06 GMT] PGpps-smalln: INFO: Test for candidate 3341*2^110243+1 accepted
[2009-08-12 15:56:06 GMT] socket 1844 <<<< End of Workunit Message
[2009-08-12 15:56:06 GMT] socket 1844 >>>> WorkUnit: 8789*2^110239+1 1250092229
[2009-08-12 15:56:06 GMT] socket 1844 <<<< INFO: Workunit found
[2009-08-12 15:56:06 GMT] socket 1844 >>>> Test Result: cllr.exe 2E7133697190F42C
[2009-08-12 15:56:06 GMT] socket 1844 >>>> End of WorkUnit
[2009-08-12 15:56:07 GMT] socket 1844 <<<< INFO: Test for candidate 8789*2^110239+1 accepted
[2009-08-12 15:56:07 GMT] PGpps-smalln: INFO: Test for candidate 8789*2^110239+1 accepted
[2009-08-12 15:56:08 GMT] socket 1844 <<<< End of Workunit Message
[2009-08-12 15:56:08 GMT] socket 1844 >>>> WorkUnit: 7295*2^110239+1 1250092229
[2009-08-12 15:56:08 GMT] socket 1844 <<<< INFO: Workunit found
[2009-08-12 15:56:08 GMT] socket 1844 >>>> Test Result: cllr.exe EE3ED5A9FB7286B4
[2009-08-12 15:56:08 GMT] socket 1844 >>>> End of WorkUnit
[2009-08-12 15:56:38 GMT] socket 1844 <<<< INFO: Test for candidate 7295*2^110239+1 accepted
[2009-08-12 15:56:38 GMT] PGpps-smalln: INFO: Test for candidate 7295*2^110239+1 accepted
[2009-08-12 15:56:40 GMT] socket 1844 <<<< End of Workunit Message
[2009-08-12 15:56:40 GMT] socket 1844 >>>> WorkUnit: 8217*2^110239+1 1250092229
[2009-08-12 15:56:55 GMT] socket 1844 <<<< ERROR: ReturnWork error. Message [End of WorkUnit] cannot be parsed
[2009-08-12 15:56:55 GMT] PGpps-smalln: ERROR: ReturnWork error. Message [End of WorkUnit] cannot be parsed
[2009-08-12 15:56:55 GMT] PGpps-smalln: The client will delete this workunit
[2009-08-12 15:56:55 GMT] socket 1844 >>>> WorkUnit: 4845*2^110240+1 1250092229
[2009-08-12 15:56:55 GMT] socket 1844 <<<< INFO: Workunit found
[2009-08-12 15:56:55 GMT] socket 1844 >>>> Test Result: cllr.exe F225CFC29FC0C3B2
[2009-08-12 15:56:55 GMT] socket 1844 >>>> End of WorkUnit
[2009-08-12 15:57:26 GMT] socket 1844 (nothing received) 
[2009-08-12 15:57:26 GMT] socket 1844 >>>> WorkUnit: 9279*2^110241+1 1250092229
[2009-08-12 15:57:26 GMT] socket 1844 <<<< INFO: Test for candidate 8217*2^110239+1 accepted
[2009-08-12 15:57:26 GMT] socket 1844 >>>> Test Result: cllr.exe 33F666C603F41A8F
[2009-08-12 15:57:26 GMT] socket 1844 >>>> End of WorkUnit
[2009-08-12 15:57:26 GMT] socket 1844 <<<< End of Workunit Message
[2009-08-12 15:57:26 GMT] socket 1844 >>>> WorkUnit: 5067*2^110242+1 1250092229
[2009-08-12 15:57:57 GMT] socket 1844 (nothing received)

It would seem that somewhere along the line, the server fell on its face during the receiving of the third-to-last result in the batch. After that, it continued answering "Workunit found" to the remaining two results, but ignored the actual results when the client sent them. As of the last line in the above excerpt, the client crashed and produced the "prpclient.exe has encountered an error and needs to close" message. No further log data was written, and the console output ends right there as well.

FYI, the client is version 2.2.4, running the official Windows binary. The server is PrimeGrid's server pgllr.mine.nu port 10000; Lennart, can you by chance pull a debug log showing the server's end of this conversation?

[mdettweiler]

Ah, I think I've also figured out where all those rejected results may be coming from. It seems that in my above example, the client never got a chance to write out the new .save file before crashing, and thus everything was still in there. When I restarted, it of course tried to send all of them again, and even though everything went smoothly this time, a number of the results were of course missing on the server since they had been successfully sent the first time around.

Possibly something like this is what's happening with all the rejected results we were seeing in the server's debug log earlier on?

[mdettweiler]

Well, that client running on my computer is sure a gold-mine of debug info. I just saw one of those weird occurrences where the client fetches the greeting, then quites without doing anything, right before my very eyes. Here's a debug log excerpt, beginning with the completion of the last of a batch of 20 WU's:

[2009-08-12 17:01:05 GMT] PGpps-smalln: 7149*2^110241+1 is not prime.  Residue 0E258C221DB38DFD
[2009-08-12 17:01:05 GMT] Total Time:  0:20:00  Total Tests: 60  Total PRPs Found: 0
Note: around 17:00:30 my internet connection cut out (which
is a rather common occurrence for me), and stayed out for
almost exactly 1 more minute. The client needed to use the
internet at 17:01:33, and when the timeout had expired 30
seconds later, it was back on.
[2009-08-12 17:01:33 GMT] in FindNextServerForWork: total time for client=1110 seconds
[2009-08-12 17:01:33 GMT] in FindNextServerForWork: total time for client=1110 seconds
[2009-08-12 17:01:38 GMT] suffix: PGpps-smalln, work done=1110, pct work done=100.000000, target pct work done=100
[2009-08-12 17:01:49 GMT] socket 1820 >>>> FROM max@noprimeleftbehind.net Core2Duo mdettweiler
[2009-08-12 17:01:49 GMT] socket 1820 >>>> GETGREETING
[2009-08-12 17:01:50 GMT] socket 1820 <<<< PRPNet Server version 2.2.3
[2009-08-12 17:01:52 GMT] socket 1820 <<<< Hello Port 10k :)
[2009-08-12 17:01:54 GMT] socket 1820 <<<< OK.
[2009-08-12 17:01:58 GMT] socket 1820 >>>> QUIT
[2009-08-12 17:02:04 GMT] Total Time:  0:20:59  Total Tests: 60  Total PRPs Found: 0
[2009-08-12 17:02:14 GMT] socket 1824 >>>> FROM max@noprimeleftbehind.net Core2Duo mdettweiler
[2009-08-12 17:02:17 GMT] PGpps-smalln: Returning work to server pgllr.mine.nu at port 10000
[2009-08-12 17:02:22 GMT] socket 1824 >>>> RETURNWORK 2.2.4
[2009-08-12 17:02:22 GMT] socket 1824 >>>> WorkUnit: 9507*2^110240+1 1250096094
[2009-08-12 17:02:25 GMT] socket 1824 <<<< INFO: Workunit found
[2009-08-12 17:02:26 GMT] socket 1824 >>>> Test Result: cllr.exe 9435F5F46E3CC752
[2009-08-12 17:02:30 GMT] socket 1824 >>>> End of WorkUnit
[2009-08-12 17:02:31 GMT] socket 1824 <<<< INFO: Test for candidate 9507*2^110240+1 accepted
[2009-08-12 17:02:31 GMT] PGpps-smalln: INFO: Test for candidate 9507*2^110240+1 accepted
[2009-08-12 17:02:31 GMT] socket 1824 <<<< End of Workunit Message
[2009-08-12 17:02:31 GMT] socket 1824 >>>> WorkUnit: 5049*2^110242+1 1250096094
[2009-08-12 17:02:31 GMT] socket 1824 <<<< INFO: Workunit found
[2009-08-12 17:02:31 GMT] socket 1824 >>>> Test Result: cllr.exe 84B24563C13EF25B
[2009-08-12 17:02:31 GMT] socket 1824 >>>> End of WorkUnit
[2009-08-12 17:02:32 GMT] socket 1824 <<<< INFO: Test for candidate 5049*2^110242+1 accepted
[2009-08-12 17:02:32 GMT] PGpps-smalln: INFO: Test for candidate 5049*2^110242+1 accepted
[2009-08-12 17:02:33 GMT] socket 1824 <<<< End of Workunit Message
[2009-08-12 17:02:33 GMT] socket 1824 >>>> WorkUnit: 1661*2^110241+1 1250096094
[2009-08-12 17:02:33 GMT] socket 1824 <<<< INFO: Workunit found
[2009-08-12 17:02:33 GMT] socket 1824 >>>> Test Result: cllr.exe 6A1ED6EC45162F50
[2009-08-12 17:02:33 GMT] socket 1824 >>>> End of WorkUnit
[2009-08-12 17:02:34 GMT] socket 1824 <<<< INFO: Test for candidate 1661*2^110241+1 accepted
[2009-08-12 17:02:34 GMT] PGpps-smalln: INFO: Test for candidate 1661*2^110241+1 accepted
[2009-08-12 17:02:34 GMT] socket 1824 <<<< End of Workunit Message
[2009-08-12 17:02:34 GMT] socket 1824 >>>> WorkUnit: 8199*2^110239+1 1250096094
[2009-08-12 17:02:34 GMT] socket 1824 <<<< INFO: Workunit found
[2009-08-12 17:02:34 GMT] socket 1824 >>>> Test Result: cllr.exe DE269021C562DBE9
[2009-08-12 17:02:34 GMT] socket 1824 >>>> End of WorkUnit
[2009-08-12 17:02:35 GMT] socket 1824 <<<< INFO: Test for candidate 8199*2^110239+1 accepted
[2009-08-12 17:02:35 GMT] PGpps-smalln: INFO: Test for candidate 8199*2^110239+1 accepted
[2009-08-12 17:02:36 GMT] socket 1824 <<<< End of Workunit Message
[2009-08-12 17:02:36 GMT] socket 1824 >>>> WorkUnit: 9627*2^110240+1 1250096094
[2009-08-12 17:02:36 GMT] socket 1824 <<<< INFO: Workunit found
[2009-08-12 17:02:36 GMT] socket 1824 >>>> Test Result: cllr.exe 696A2EC91888710A
[2009-08-12 17:02:36 GMT] socket 1824 >>>> End of WorkUnit
[2009-08-12 17:02:37 GMT] socket 1824 <<<< INFO: Test for candidate 9627*2^110240+1 accepted
[2009-08-12 17:02:37 GMT] PGpps-smalln: INFO: Test for candidate 9627*2^110240+1 accepted
[2009-08-12 17:02:37 GMT] socket 1824 <<<< End of Workunit Message
[2009-08-12 17:02:37 GMT] socket 1824 >>>> WorkUnit: 7673*2^110241+1 1250096094
[2009-08-12 17:02:37 GMT] socket 1824 <<<< INFO: Workunit found
[2009-08-12 17:02:37 GMT] socket 1824 >>>> Test Result: cllr.exe B44D33A7468E4C2C
[2009-08-12 17:02:37 GMT] socket 1824 >>>> End of WorkUnit
[2009-08-12 17:02:38 GMT] socket 1824 <<<< INFO: Test for candidate 7673*2^110241+1 accepted
[2009-08-12 17:02:38 GMT] PGpps-smalln: INFO: Test for candidate 7673*2^110241+1 accepted
[2009-08-12 17:02:38 GMT] socket 1824 <<<< End of Workunit Message
[2009-08-12 17:02:38 GMT] socket 1824 >>>> WorkUnit: 7161*2^110240+1 1250096094
[2009-08-12 17:02:39 GMT] socket 1824 <<<< INFO: Workunit found
[2009-08-12 17:02:39 GMT] socket 1824 >>>> Test Result: cllr.exe EA70E37516AD26BD
[2009-08-12 17:02:39 GMT] socket 1824 >>>> End of WorkUnit
[2009-08-12 17:02:39 GMT] socket 1824 <<<< INFO: Test for candidate 7161*2^110240+1 accepted
[2009-08-12 17:02:39 GMT] PGpps-smalln: INFO: Test for candidate 7161*2^110240+1 accepted
[2009-08-12 17:02:40 GMT] socket 1824 <<<< End of Workunit Message
[2009-08-12 17:02:40 GMT] socket 1824 >>>> WorkUnit: 9223*2^110240+1 1250096094
[2009-08-12 17:02:41 GMT] socket 1824 <<<< INFO: Workunit found
[2009-08-12 17:02:41 GMT] socket 1824 >>>> Test Result: cllr.exe 0962852078165F75
[2009-08-12 17:02:41 GMT] socket 1824 >>>> End of WorkUnit
[2009-08-12 17:02:41 GMT] socket 1824 <<<< INFO: Test for candidate 9223*2^110240+1 accepted
[2009-08-12 17:02:41 GMT] PGpps-smalln: INFO: Test for candidate 9223*2^110240+1 accepted
[2009-08-12 17:02:42 GMT] socket 1824 <<<< End of Workunit Message
[2009-08-12 17:02:42 GMT] socket 1824 >>>> WorkUnit: 1871*2^110241+1 1250096094
[2009-08-12 17:02:42 GMT] socket 1824 <<<< INFO: Workunit found
[2009-08-12 17:02:42 GMT] socket 1824 >>>> Test Result: cllr.exe C5F37DEC45408ABA
[2009-08-12 17:02:42 GMT] socket 1824 >>>> End of WorkUnit
[2009-08-12 17:02:43 GMT] socket 1824 <<<< INFO: Test for candidate 1871*2^110241+1 accepted
[2009-08-12 17:02:43 GMT] PGpps-smalln: INFO: Test for candidate 1871*2^110241+1 accepted
[2009-08-12 17:02:43 GMT] socket 1824 <<<< End of Workunit Message
[2009-08-12 17:02:43 GMT] socket 1824 >>>> WorkUnit: 2273*2^110241+1 1250096094
[2009-08-12 17:02:44 GMT] socket 1824 <<<< INFO: Workunit found
[2009-08-12 17:02:44 GMT] socket 1824 >>>> Test Result: cllr.exe 814379B84F9146F5
[2009-08-12 17:02:44 GMT] socket 1824 >>>> End of WorkUnit
[2009-08-12 17:02:44 GMT] socket 1824 <<<< INFO: Test for candidate 2273*2^110241+1 accepted
[2009-08-12 17:02:44 GMT] PGpps-smalln: INFO: Test for candidate 2273*2^110241+1 accepted
[2009-08-12 17:02:45 GMT] socket 1824 <<<< End of Workunit Message
[2009-08-12 17:02:45 GMT] socket 1824 >>>> WorkUnit: 5715*2^110240+1 1250096094
[2009-08-12 17:02:45 GMT] socket 1824 <<<< INFO: Workunit found
[2009-08-12 17:02:45 GMT] socket 1824 >>>> Test Result: cllr.exe 75A021F2ACFAB6EC
[2009-08-12 17:02:45 GMT] socket 1824 >>>> End of WorkUnit
[2009-08-12 17:02:46 GMT] socket 1824 <<<< INFO: Test for candidate 5715*2^110240+1 accepted
[2009-08-12 17:02:46 GMT] PGpps-smalln: INFO: Test for candidate 5715*2^110240+1 accepted
[2009-08-12 17:02:46 GMT] socket 1824 <<<< End of Workunit Message
[2009-08-12 17:02:46 GMT] socket 1824 >>>> WorkUnit: 4615*2^110240+1 1250096094
[2009-08-12 17:02:47 GMT] socket 1824 <<<< INFO: Workunit found
[2009-08-12 17:02:47 GMT] socket 1824 >>>> Test Result: cllr.exe 2F4DB72AE30EF794
[2009-08-12 17:02:47 GMT] socket 1824 >>>> End of WorkUnit
[2009-08-12 17:02:47 GMT] socket 1824 <<<< INFO: Test for candidate 4615*2^110240+1 accepted
[2009-08-12 17:02:47 GMT] PGpps-smalln: INFO: Test for candidate 4615*2^110240+1 accepted
[2009-08-12 17:02:48 GMT] socket 1824 <<<< End of Workunit Message
[2009-08-12 17:02:48 GMT] socket 1824 >>>> WorkUnit: 8197*2^110240+1 1250096094
[2009-08-12 17:02:48 GMT] socket 1824 <<<< INFO: Workunit found
[2009-08-12 17:02:48 GMT] socket 1824 >>>> Test Result: cllr.exe 34E0DF93E2583422
[2009-08-12 17:02:48 GMT] socket 1824 >>>> End of WorkUnit
[2009-08-12 17:02:49 GMT] socket 1824 <<<< INFO: Test for candidate 8197*2^110240+1 accepted
[2009-08-12 17:02:49 GMT] PGpps-smalln: INFO: Test for candidate 8197*2^110240+1 accepted
[2009-08-12 17:02:49 GMT] socket 1824 <<<< End of Workunit Message
[2009-08-12 17:02:49 GMT] socket 1824 >>>> WorkUnit: 4617*2^110240+1 1250096094
[2009-08-12 17:02:49 GMT] socket 1824 <<<< INFO: Workunit found
[2009-08-12 17:02:49 GMT] socket 1824 >>>> Test Result: cllr.exe 5CB83C67C9719114
[2009-08-12 17:02:49 GMT] socket 1824 >>>> End of WorkUnit
...etc, more normally returned workunits snipped for size

Is the "log on and quit immediately" thing possibly a normal thing the client does to check whether the server's back online before trying to return its work?

BTW: you can ignore the fact that the times seem a little sluggish. That was because while the internet was out and the client was waiting for its timeout, I temporarily switched on another application to keep that core busy. I switched it back off about two or three results into the communication where the client returned its results to the server normally, having noticed that the client's speed at returning the results was being impacted.