WU not being received by my computer

Forums › Problems and Bug Reports

Mark Reiss
Mark Reiss
Joined: 22 Jan 05
Posts: 16
Credit: 1996687
RAC: 0
7 May 2005 13:01:00 UTC
Topic 189125
(moderation:
    )

    H E L P ! ! I have my prefrences set to 7 days and keep requesting more WU (Currently have 3) boinc shows WU have been assigned to this computer but I am not getting them.? messages say max of 8 quota reached!

    Bruce Allen
    Bruce Allen
    Moderator
    Joined: 15 Oct 04
    Posts: 1119
    Credit: 172127663
    RAC: 0

    WU not being received by my computer

    7 May 2005 14:10:14 UTC
    Message 11406
    (moderation:
      )

      H E L P ! ! I have my prefrences set to 7 days and keep requesting more WU (Currently have 3) boinc shows WU have been assigned to this computer but I am not getting them.? messages say max of 8 quota reached!

      Mark, has this problem been happening consistently? We are still trying to track down what's going on when WU go missing. Do you have any sort of firewall or proxy server set up?

      Bruce

      Director, Einstein@Home

      Mark Reiss
      Mark Reiss
      Joined: 22 Jan 05
      Posts: 16
      Credit: 1996687
      RAC: 0

      Got problem solved by

      8 May 2005 1:20:24 UTC
      Message 11407 in response to message 11406
      (moderation:
        )

        Got problem solved by switching from boinc 4.19 to boinc 4.37 Thanks - Mark Reiss

        Mark Reiss
        Mark Reiss
        Joined: 22 Jan 05
        Posts: 16
        Credit: 1996687
        RAC: 0

        Got problem solved by

        9 May 2005 3:44:29 UTC
        Message 11408 in response to message 11407
        (moderation:
          )

          Got problem solved by switching from boinc 4.19 to boinc 4.37 Thanks - Mark Reiss

          As of 05/08/05 @ 23:41 New york Time - WU not uploading and total credit and avg. credit not updating. No firewall or proxy in effect. Currently using BOINC v 4.37

          Thanks -- Mark Reiss

          Mark Reiss
          Mark Reiss
          Joined: 22 Jan 05
          Posts: 16
          Credit: 1996687
          RAC: 0

          Got problem solved by

          9 May 2005 3:52:07 UTC
          Message 11409 in response to message 11408
          (moderation:
            )

            Got problem solved by switching from boinc 4.19 to boinc 4.37 Thanks - Mark Reiss

            As of 05/08/05 @ 23:41 New york Time - WU not uploading and total credit and avg. credit not updating. No firewall or proxy in effect. Currently using BOINC v 4.37

            Thanks -- Mark Reiss

            As of 05/08/05 @ 23:50 New York Time - Was able to send in WU & get totals updated by clicking on no new work within projects tab twice.

            Thanks -- Mark Reiss

            ralic
            ralic
            Joined: 8 Nov 04
            Posts: 128
            Credit: 695810
            RAC: 0

            Mark, has this problem been

            9 May 2005 14:46:06 UTC
            Message 11410 in response to message 11406
            (moderation:
              )

              Mark, has this problem been happening consistently? We are still trying to track down what's going on when WU go missing. Do you have any sort of firewall or proxy server set up?

              Bruce

              Hi Bruce
              Just had the same bad experience on a host that is usually very reliable. Messages are posted below for futher diagnosis, but a cursory examination indicates that the scheduler assigns the work to the host, even though it is not confirmed as received by the host. Ultimately, the host cannot request more because of the quota limit. In my case there is a proxy between the host and the net, and as can be seen from the messages, the uploads proceed fine, but the scheduler response is not received.
              HostID in question is: 61874
              BOINC V4.26 for windows.

              I feel sure that tomorrow the host will be able to receive work again, but I'm rather annoyed with the host because of the 16 results that are wasted. If you have any further questions, please let me know. I'd be keen to know what your server logs can unearth. The times in the messages files are local, which is UTC+2.

              begin messages:
              09/05/2005 16:33:31||Resuming network activity
              09/05/2005 16:33:32||Insufficient work; requesting more
              09/05/2005 16:33:32|Einstein@Home|Requesting 518400.00 seconds of work
              09/05/2005 16:33:32|Einstein@Home|Sending request to scheduler: http://einstein.phys.uwm.edu/EinsteinAtHome_cgi/cgi
              09/05/2005 16:33:32|Einstein@Home|Started upload of H1_0723.4__0723.9_0.1_T15_Run2_1_0
              09/05/2005 16:33:32|Einstein@Home|Started upload of H1_0723.4__0723.5_0.1_T16_Run2_1_0
              09/05/2005 16:34:03|Einstein@Home|Scheduler RPC to http://einstein.phys.uwm.edu/EinsteinAtHome_cgi/cgi failed
              09/05/2005 16:34:03|Einstein@Home|No schedulers responded
              09/05/2005 16:34:03|Einstein@Home|Deferring communication with project for 1 minutes and 0 seconds
              09/05/2005 16:34:12|Einstein@Home|Finished upload of H1_0723.4__0723.9_0.1_T15_Run2_1_0
              09/05/2005 16:34:12|Einstein@Home|Throughput 508424 bytes/sec
              09/05/2005 16:34:12|Einstein@Home|Started upload of H1_0723.4__0723.8_0.1_T16_Run2_3_0
              09/05/2005 16:34:43|Einstein@Home|Finished upload of H1_0723.4__0723.8_0.1_T16_Run2_3_0
              09/05/2005 16:34:43|Einstein@Home|Throughput 95129 bytes/sec
              09/05/2005 16:34:43|Einstein@Home|Started upload of H1_0723.4__0723.8_0.1_T05_Run2_5_0
              09/05/2005 16:34:46|Einstein@Home|Finished upload of H1_0723.4__0723.5_0.1_T16_Run2_1_0
              09/05/2005 16:34:46|Einstein@Home|Throughput 3862 bytes/sec
              09/05/2005 16:34:46|Einstein@Home|Started upload of H1_0723.4__0723.7_0.1_T15_Run2_4_0
              09/05/2005 16:34:53|Einstein@Home|Finished upload of H1_0723.4__0723.8_0.1_T05_Run2_5_0
              09/05/2005 16:34:53|Einstein@Home|Throughput 862400 bytes/sec
              09/05/2005 16:34:53|Einstein@Home|Started upload of H1_0659.0__0659.4_0.1_T00_Fin1_2_0
              09/05/2005 16:35:04||Insufficient work; requesting more
              09/05/2005 16:35:04|Einstein@Home|Requesting 518400.00 seconds of work
              09/05/2005 16:35:04|Einstein@Home|Sending request to scheduler: http://einstein.phys.uwm.edu/EinsteinAtHome_cgi/cgi
              09/05/2005 16:35:11|Einstein@Home|Finished upload of H1_0723.4__0723.7_0.1_T15_Run2_4_0
              09/05/2005 16:35:11|Einstein@Home|Throughput 345638 bytes/sec
              09/05/2005 16:35:11|Einstein@Home|Started upload of H1_0659.0__0659.0_0.1_T01_Fin1_3_0
              09/05/2005 16:35:32|Einstein@Home|Finished upload of H1_0659.0__0659.4_0.1_T00_Fin1_2_0
              09/05/2005 16:35:32|Einstein@Home|Throughput 294852 bytes/sec
              09/05/2005 16:35:32|Einstein@Home|Started upload of H1_0659.0__0659.1_0.1_T01_Fin1_2_0
              09/05/2005 16:35:35|Einstein@Home|Finished upload of H1_0659.0__0659.0_0.1_T01_Fin1_3_0
              09/05/2005 16:35:35|Einstein@Home|Throughput 669632 bytes/sec
              09/05/2005 16:35:35|Einstein@Home|Started upload of H1_0659.0__0659.1_0.1_T00_Fin1_5_0
              09/05/2005 16:35:40|Einstein@Home|Scheduler RPC to http://einstein.phys.uwm.edu/EinsteinAtHome_cgi/cgi failed
              09/05/2005 16:35:40|Einstein@Home|No schedulers responded
              09/05/2005 16:35:40|Einstein@Home|Deferring communication with project for 1 minutes and 0 seconds
              09/05/2005 16:36:08|Einstein@Home|Finished upload of H1_0659.0__0659.1_0.1_T01_Fin1_2_0
              09/05/2005 16:36:08|Einstein@Home|Throughput 720821 bytes/sec
              09/05/2005 16:36:08|Einstein@Home|Started upload of H1_0659.0__0659.2_0.1_T01_Fin1_1_0
              09/05/2005 16:36:41||Insufficient work; requesting more
              09/05/2005 16:36:41|Einstein@Home|Requesting 518400.00 seconds of work
              09/05/2005 16:36:41|Einstein@Home|Sending request to scheduler: http://einstein.phys.uwm.edu/EinsteinAtHome_cgi/cgi
              09/05/2005 16:37:07|Einstein@Home|Scheduler RPC to http://einstein.phys.uwm.edu/EinsteinAtHome_cgi/cgi succeeded
              09/05/2005 16:37:07|Einstein@Home|Message from server: No work sent
              09/05/2005 16:37:07|Einstein@Home|Message from server: (reached daily quota of 16 results)
              09/05/2005 16:37:07|Einstein@Home|No work from project
              09/05/2005 16:37:07|Einstein@Home|Deferring communication with project for 1 hours, 0 minutes, and 0 seconds
              09/05/2005 16:37:17|Einstein@Home|Finished upload of H1_0659.0__0659.1_0.1_T00_Fin1_5_0
              09/05/2005 16:37:17|Einstein@Home|Throughput 5132 bytes/sec
              09/05/2005 16:37:18|Einstein@Home|Finished upload of H1_0659.0__0659.2_0.1_T01_Fin1_1_0
              09/05/2005 16:37:18|Einstein@Home|Throughput 39340 bytes/sec
              09/05/2005 16:41:57||Suspending network activity - user request

              Kevin N. Shapley
              Kevin N. Shapley
              Joined: 9 Feb 05
              Posts: 1
              Credit: 45883
              RAC: 0

              Just to add my own troubles

              10 May 2005 0:31:13 UTC
              Message 11411
              (moderation:
                )


                Just to add my own troubles to the list. I just switched from 4.19 to 4.25 a few days ago.

                I am now having the same problem. WU's are listed on the results page of my account but have not made it to my computers.

                Einstein is the only project to have this behaviour, Seti, LCH, Protein all work flawlessly.

                ralic
                ralic
                Joined: 8 Nov 04
                Posts: 128
                Credit: 695810
                RAC: 0

                Einstein is the only project

                10 May 2005 7:21:19 UTC
                Message 11412 in response to message 11411
                (moderation:
                  )


                  Einstein is the only project to have this behaviour, Seti, LCH, Protein all work flawlessly.

                  Actually, I've seen this before on SETI about a month ago. Different host than this one though, and with BOINC v4.25. Only affected about 7 or 8 WU's, IIRC.

                  I suspect that the scheduler request->assign->send->acknowledge logic is a bit flawed and fails under certain conditions. If I get a chance, I'll try and figure it out and see if I can spot anything that looks like a problem.

                  ralic
                  ralic
                  Joined: 8 Nov 04
                  Posts: 128
                  Credit: 695810
                  RAC: 0

                  I feel sure that tomorrow the

                  10 May 2005 9:00:51 UTC
                  Message 11413 in response to message 11410
                  (moderation:
                    )

                    I feel sure that tomorrow the host will be able to receive work again,...

                    Well, another two scheduler requests, another 16 WU's assigned and another two "No schedulers responded" today. :(

                    To troubleshoot this, I'm going to put my proxy in full debug mode and capture everything that's being sent and received.

                    Unfortunately, it'll be another 24 hours before I'll be able to report back. If I try again now, I'll just get another "reached daily quota" reply...

                    Bruce Allen
                    Bruce Allen
                    Moderator
                    Joined: 15 Oct 04
                    Posts: 1119
                    Credit: 172127663
                    RAC: 0

                    Mark, has this problem been

                    10 May 2005 13:56:57 UTC
                    Message 11414 in response to message 11410
                    (moderation:
                      )

                      Mark, has this problem been happening consistently? We are still trying to track down what's going on when WU go missing. Do you have any sort of firewall or proxy server set up?

                      Bruce

                      Hi Bruce
                      Just had the same bad experience on a host that is usually very reliable. Messages are posted below for futher diagnosis, but a cursory examination indicates that the scheduler assigns the work to the host, even though it is not confirmed as received by the host. Ultimately, the host cannot request more because of the quota limit. In my case there is a proxy between the host and the net, and as can be seen from the messages, the uploads proceed fine, but the scheduler response is not received.
                      HostID in question is: 61874
                      BOINC V4.26 for windows.

                      I feel sure that tomorrow the host will be able to receive work again, but I'm rather annoyed with the host because of the 16 results that are wasted. If you have any further questions, please let me know. I'd be keen to know what your server logs can unearth. The times in the messages files are local, which is UTC+2.

                      begin messages:
                      09/05/2005 16:33:31||Resuming network activity
                      09/05/2005 16:33:32||Insufficient work; requesting more
                      09/05/2005 16:33:32|Einstein@Home|Requesting 518400.00 seconds of work
                      09/05/2005 16:33:32|Einstein@Home|Sending request to scheduler: http://einstein.phys.uwm.edu/EinsteinAtHome_cgi/cgi
                      09/05/2005 16:33:32|Einstein@Home|Started upload of H1_0723.4__0723.9_0.1_T15_Run2_1_0
                      09/05/2005 16:33:32|Einstein@Home|Started upload of H1_0723.4__0723.5_0.1_T16_Run2_1_0
                      09/05/2005 16:34:03|Einstein@Home|Scheduler RPC to http://einstein.phys.uwm.edu/EinsteinAtHome_cgi/cgi failed
                      09/05/2005 16:34:03|Einstein@Home|No schedulers responded
                      09/05/2005 16:34:03|Einstein@Home|Deferring communication with project for 1 minutes and 0 seconds
                      09/05/2005 16:34:12|Einstein@Home|Finished upload of H1_0723.4__0723.9_0.1_T15_Run2_1_0
                      09/05/2005 16:34:12|Einstein@Home|Throughput 508424 bytes/sec
                      09/05/2005 16:34:12|Einstein@Home|Started upload of H1_0723.4__0723.8_0.1_T16_Run2_3_0
                      09/05/2005 16:34:43|Einstein@Home|Finished upload of H1_0723.4__0723.8_0.1_T16_Run2_3_0
                      09/05/2005 16:34:43|Einstein@Home|Throughput 95129 bytes/sec
                      09/05/2005 16:34:43|Einstein@Home|Started upload of H1_0723.4__0723.8_0.1_T05_Run2_5_0
                      09/05/2005 16:34:46|Einstein@Home|Finished upload of H1_0723.4__0723.5_0.1_T16_Run2_1_0
                      09/05/2005 16:34:46|Einstein@Home|Throughput 3862 bytes/sec
                      09/05/2005 16:34:46|Einstein@Home|Started upload of H1_0723.4__0723.7_0.1_T15_Run2_4_0
                      09/05/2005 16:34:53|Einstein@Home|Finished upload of H1_0723.4__0723.8_0.1_T05_Run2_5_0
                      09/05/2005 16:34:53|Einstein@Home|Throughput 862400 bytes/sec
                      09/05/2005 16:34:53|Einstein@Home|Started upload of H1_0659.0__0659.4_0.1_T00_Fin1_2_0
                      09/05/2005 16:35:04||Insufficient work; requesting more
                      09/05/2005 16:35:04|Einstein@Home|Requesting 518400.00 seconds of work
                      09/05/2005 16:35:04|Einstein@Home|Sending request to scheduler: http://einstein.phys.uwm.edu/EinsteinAtHome_cgi/cgi
                      09/05/2005 16:35:11|Einstein@Home|Finished upload of H1_0723.4__0723.7_0.1_T15_Run2_4_0
                      09/05/2005 16:35:11|Einstein@Home|Throughput 345638 bytes/sec
                      09/05/2005 16:35:11|Einstein@Home|Started upload of H1_0659.0__0659.0_0.1_T01_Fin1_3_0
                      09/05/2005 16:35:32|Einstein@Home|Finished upload of H1_0659.0__0659.4_0.1_T00_Fin1_2_0
                      09/05/2005 16:35:32|Einstein@Home|Throughput 294852 bytes/sec
                      09/05/2005 16:35:32|Einstein@Home|Started upload of H1_0659.0__0659.1_0.1_T01_Fin1_2_0
                      09/05/2005 16:35:35|Einstein@Home|Finished upload of H1_0659.0__0659.0_0.1_T01_Fin1_3_0
                      09/05/2005 16:35:35|Einstein@Home|Throughput 669632 bytes/sec
                      09/05/2005 16:35:35|Einstein@Home|Started upload of H1_0659.0__0659.1_0.1_T00_Fin1_5_0
                      09/05/2005 16:35:40|Einstein@Home|Scheduler RPC to http://einstein.phys.uwm.edu/EinsteinAtHome_cgi/cgi failed
                      09/05/2005 16:35:40|Einstein@Home|No schedulers responded
                      09/05/2005 16:35:40|Einstein@Home|Deferring communication with project for 1 minutes and 0 seconds
                      09/05/2005 16:36:08|Einstein@Home|Finished upload of H1_0659.0__0659.1_0.1_T01_Fin1_2_0
                      09/05/2005 16:36:08|Einstein@Home|Throughput 720821 bytes/sec
                      09/05/2005 16:36:08|Einstein@Home|Started upload of H1_0659.0__0659.2_0.1_T01_Fin1_1_0
                      09/05/2005 16:36:41||Insufficient work; requesting more
                      09/05/2005 16:36:41|Einstein@Home|Requesting 518400.00 seconds of work
                      09/05/2005 16:36:41|Einstein@Home|Sending request to scheduler: http://einstein.phys.uwm.edu/EinsteinAtHome_cgi/cgi
                      09/05/2005 16:37:07|Einstein@Home|Scheduler RPC to http://einstein.phys.uwm.edu/EinsteinAtHome_cgi/cgi succeeded
                      09/05/2005 16:37:07|Einstein@Home|Message from server: No work sent
                      09/05/2005 16:37:07|Einstein@Home|Message from server: (reached daily quota of 16 results)
                      09/05/2005 16:37:07|Einstein@Home|No work from project
                      09/05/2005 16:37:07|Einstein@Home|Deferring communication with project for 1 hours, 0 minutes, and 0 seconds
                      09/05/2005 16:37:17|Einstein@Home|Finished upload of H1_0659.0__0659.1_0.1_T00_Fin1_5_0
                      09/05/2005 16:37:17|Einstein@Home|Throughput 5132 bytes/sec
                      09/05/2005 16:37:18|Einstein@Home|Finished upload of H1_0659.0__0659.2_0.1_T01_Fin1_1_0
                      09/05/2005 16:37:18|Einstein@Home|Throughput 39340 bytes/sec
                      09/05/2005 16:41:57||Suspending network activity - user request

                      Here is the relevant part of the scheduler log. The basic problem seems to be that on your end the core client timed out after 36 seconds, whereas on the server, the scheduler continued to run for 61 seconds. I am making some inquiries with the BOINC developers to try and understand if the core client has a time-out which might have caused this broken connection and hence the lost WU.

                      PS: you might want to use ntp or some other method to set the correct time on your machine. It's off by a few minutes.

                      Cheers,
                      Bruce

                      2005-05-09 14:26:14 [PID=26946] [debug ] REQUEST_METHOD=POST CONTENT_TYPE=application/octet-stream HTTP_ACCEPT= HTTP_USER_AGENT=BOINC client (windows_intelx86 4.26)
                      2005-05-09 14:26:14 [PID=26946] [debug ] CONTENT_LENGTH=5893 from X.X.X.X
                      2005-05-09 14:26:15 [PID=26946] [normal ] Handling request: IP X.X.X.X, auth XXX, host 61874, platform windows_intelx86, version 4.26
                      2005-05-09 14:26:15 [PID=26946] [normal ] OS version Microsoft Windows XP Professional Edition, Service Pack 2, (05.01.2600.00)
                      2005-05-09 14:26:15 [PID=26946] [debug ] Request [HOST#61874] Database [HOST#61874] Request [RPC#91] Database [RPC#84]
                      2005-05-09 14:26:15 [PID=26946] [normal ] Processing request from [USER#167] [HOST#61874] [IP X.X.X.X] [RPC#91] core client version 4.26
                      2005-05-09 14:26:15 [PID=26946] [debug ] [HOST#61874] Resetting nresults_today
                      2005-05-09 14:26:15 [PID=26946] [normal ] [HOST#61874] [RESULT#3911567 H1_0723.4__0723.5_0.1_T15_Run2_1] got result
                      2005-05-09 14:26:15 [PID=26946] [debug ] cpu 42878.468750 cpcs 0.001458, cc 62.521891
                      2005-05-09 14:26:15 [PID=26946] [debug ] [RESULT#3911567 H1_0723.4__0723.5_0.1_T15_Run2_1]: setting outcome SUCCESS
                      2005-05-09 14:26:15 [PID=26946] [normal ] [HOST#61874] [RESULT#3915377 H1_0723.4__0723.8_0.1_T15_Run2_2] got result
                      2005-05-09 14:26:15 [PID=26946] [debug ] cpu 42308.968750 cpcs 0.001458, cc 61.691492
                      2005-05-09 14:26:15 [PID=26946] [debug ] [RESULT#3915377 H1_0723.4__0723.8_0.1_T15_Run2_2]: setting outcome SUCCESS
                      2005-05-09 14:26:15 [PID=26946] [normal ] [HOST#61874] got request for 518400.000000 seconds of work; available disk 14.636548 GB
                      2005-05-09 14:26:15 [PID=26946] [debug ] [HOST#61874]: has file H1_0659.0
                      2005-05-09 14:26:15 [PID=26946] [debug ] in_send_results_for_file(H1_0659.0, 0) prev_result.id=4103282
                      2005-05-09 14:26:15 [PID=26946] [debug ] Sorted list of URLs follows [host timezone: UTC+7200]
                      2005-05-09 14:26:15 [PID=26946] [debug ] zone=+03600 url=http://einstein.aei.mpg.de
                      2005-05-09 14:26:15 [PID=26946] [debug ] zone=+00000 url=http://einstein.astro.gla.ac.uk
                      2005-05-09 14:26:15 [PID=26946] [debug ] zone=-18000 url=http://einstein.aset.psu.edu
                      2005-05-09 14:26:15 [PID=26946] [debug ] zone=-18000 url=http://morel.mit.edu
                      2005-05-09 14:26:15 [PID=26946] [debug ] zone=-21600 url=http://einstein.phys.uwm.edu
                      2005-05-09 14:26:15 [PID=26946] [debug ] [HOST#61874] Sending app_version einstein windows_intelx86 479
                      2005-05-09 14:26:15 [PID=26946] [debug ] [HOST#61874] Already has file H1_0659.0
                      2005-05-09 14:26:15 [PID=26946] [debug ] [HOST#61874] reducing disk needed for WU by 14736000 bytes (length of H1_0659.0)
                      2005-05-09 14:26:15 [PID=26946] [debug ] est cpu dur 30069.284065; running_frac 0.930656; rsf 0.500000; est 64619.523091
                      2005-05-09 14:26:15 [PID=26946] [normal ] [HOST#61874] Sending [RESULT#4160517 H1_0659.0__0659.0_0.1_T02_Fin1_3] (fills 64619.52 seconds)
                      2005-05-09 14:26:15 [PID=26946] [debug ] in_send_results_for_file(H1_0659.0, 1) prev_result.id=4160517
                      2005-05-09 14:26:15 [PID=26946] [debug ] est cpu dur 30069.284065; running_frac 0.930656; rsf 0.500000; est 64619.523091
                      2005-05-09 14:26:15 [PID=26946] [debug ] [HOST#61874] Sending app_version einstein windows_intelx86 479
                      2005-05-09 14:26:15 [PID=26946] [debug ] [HOST#61874] Already has file H1_0659.0
                      2005-05-09 14:26:15 [PID=26946] [debug ] [HOST#61874] reducing disk needed for WU by 14736000 bytes (length of H1_0659.0)
                      2005-05-09 14:26:15 [PID=26946] [debug ] est cpu dur 30069.284065; running_frac 0.930656; rsf 0.500000; est 64619.523091
                      2005-05-09 14:26:15 [PID=26946] [normal ] [HOST#61874] Sending [RESULT#4172748 H1_0659.0__0659.1_0.1_T02_Fin1_1] (fills 64619.52 seconds)
                      2005-05-09 14:26:15 [PID=26946] [debug ] in_send_results_for_file(H1_0659.0, 2) prev_result.id=4172748
                      2005-05-09 14:26:15 [PID=26946] [debug ] touched ../locality_scheduling/need_work/H1_0659.0: need work for file H1_0659.0
                      2005-05-09 14:26:15 [PID=26946] [debug ] make_more_work_for_file(H1_0659.0, 2)=0
                      2005-05-09 14:26:25 [PID=26946] [debug ] in_send_results_for_file(H1_0659.0, 3) prev_result.id=4172748
                      2005-05-09 14:26:25 [PID=26946] [debug ] est cpu dur 30069.284065; running_frac 0.930656; rsf 0.500000; est 64619.523091
                      2005-05-09 14:26:25 [PID=26946] [debug ] [HOST#61874] Sending app_version einstein windows_intelx86 479
                      2005-05-09 14:26:25 [PID=26946] [debug ] [HOST#61874] Already has file H1_0659.0
                      2005-05-09 14:26:25 [PID=26946] [debug ] [HOST#61874] reducing disk needed for WU by 14736000 bytes (length of H1_0659.0)
                      2005-05-09 14:26:25 [PID=26946] [debug ] est cpu dur 30069.284065; running_frac 0.930656; rsf 0.500000; est 64619.523091
                      2005-05-09 14:26:25 [PID=26946] [normal ] [HOST#61874] Sending [RESULT#4192499 H1_0659.0__0659.2_0.1_T02_Fin1_0] (fills 64619.52 seconds)
                      2005-05-09 14:26:25 [PID=26946] [debug ] in_send_results_for_file(H1_0659.0, 4) prev_result.id=4192499
                      2005-05-09 14:26:25 [PID=26946] [debug ] touched ../locality_scheduling/need_work/H1_0659.0: need work for file H1_0659.0
                      2005-05-09 14:26:25 [PID=26946] [debug ] make_more_work_for_file(H1_0659.0, 4)=0
                      2005-05-09 14:26:35 [PID=26946] [debug ] in_send_results_for_file(H1_0659.0, 5) prev_result.id=4192499
                      2005-05-09 14:26:35 [PID=26946] [debug ] est cpu dur 30069.284065; running_frac 0.930656; rsf 0.500000; est 64619.523091
                      2005-05-09 14:26:35 [PID=26946] [debug ] [HOST#61874] Sending app_version einstein windows_intelx86 479
                      2005-05-09 14:26:35 [PID=26946] [debug ] [HOST#61874] Already has file H1_0659.0
                      2005-05-09 14:26:35 [PID=26946] [debug ] [HOST#61874] reducing disk needed for WU by 14736000 bytes (length of H1_0659.0)
                      2005-05-09 14:26:35 [PID=26946] [debug ] est cpu dur 30069.284065; running_frac 0.930656; rsf 0.500000; est 64619.523091
                      2005-05-09 14:26:35 [PID=26946] [normal ] [HOST#61874] Sending [RESULT#4192517 H1_0659.0__0659.3_0.1_T02_Fin1_0] (fills 64619.52 seconds)
                      2005-05-09 14:26:35 [PID=26946] [debug ] in_send_results_for_file(H1_0659.0, 6) prev_result.id=4192517
                      2005-05-09 14:26:35 [PID=26946] [debug ] touched ../locality_scheduling/need_work/H1_0659.0: need work for file H1_0659.0
                      2005-05-09 14:26:35 [PID=26946] [debug ] make_more_work_for_file(H1_0659.0, 6)=0
                      2005-05-09 14:26:45 [PID=26946] [debug ] in_send_results_for_file(H1_0659.0, 7) prev_result.id=4192517
                      2005-05-09 14:26:45 [PID=26946] [debug ] est cpu dur 30069.284065; running_frac 0.930656; rsf 0.500000; est 64619.523091
                      2005-05-09 14:26:45 [PID=26946] [debug ] [HOST#61874] Sending app_version einstein windows_intelx86 479
                      2005-05-09 14:26:45 [PID=26946] [debug ] [HOST#61874] Already has file H1_0659.0
                      2005-05-09 14:26:45 [PID=26946] [debug ] [HOST#61874] reducing disk needed for WU by 14736000 bytes (length of H1_0659.0)
                      2005-05-09 14:26:45 [PID=26946] [debug ] est cpu dur 30069.284065; running_frac 0.930656; rsf 0.500000; est 64619.523091
                      2005-05-09 14:26:45 [PID=26946] [normal ] [HOST#61874] Sending [RESULT#4192533 H1_0659.0__0659.4_0.1_T02_Fin1_0] (fills 64619.52 seconds)
                      2005-05-09 14:26:45 [PID=26946] [debug ] in_send_results_for_file(H1_0659.0, 8) prev_result.id=4192533
                      2005-05-09 14:26:45 [PID=26946] [debug ] touched ../locality_scheduling/need_work/H1_0659.0: need work for file H1_0659.0
                      2005-05-09 14:26:45 [PID=26946] [debug ] make_more_work_for_file(H1_0659.0, 8)=0
                      2005-05-09 14:26:55 [PID=26946] [debug ] in_send_results_for_file(H1_0659.0, 9) prev_result.id=4192533
                      2005-05-09 14:26:55 [PID=26946] [debug ] est cpu dur 30069.284065; running_frac 0.930656; rsf 0.500000; est 64619.523091
                      2005-05-09 14:26:55 [PID=26946] [debug ] [HOST#61874] Sending app_version einstein windows_intelx86 479
                      2005-05-09 14:26:55 [PID=26946] [debug ] [HOST#61874] Already has file H1_0659.0
                      2005-05-09 14:26:55 [PID=26946] [debug ] [HOST#61874] reducing disk needed for WU by 14736000 bytes (length of H1_0659.0)
                      2005-05-09 14:26:55 [PID=26946] [debug ] est cpu dur 30069.284065; running_frac 0.930656; rsf 0.500000; est 64619.523091
                      2005-05-09 14:26:55 [PID=26946] [normal ] [HOST#61874] Sending [RESULT#4192550 H1_0659.0__0659.0_0.1_T03_Fin1_0] (fills 64619.52 seconds)
                      2005-05-09 14:26:55 [PID=26946] [debug ] in_send_results_for_file(H1_0659.0, 10) prev_result.id=4192550
                      2005-05-09 14:26:55 [PID=26946] [debug ] touched ../locality_scheduling/need_work/H1_0659.0: need work for file H1_0659.0
                      2005-05-09 14:26:55 [PID=26946] [debug ] make_more_work_for_file(H1_0659.0, 10)=0
                      2005-05-09 14:27:05 [PID=26946] [debug ] in_send_results_for_file(H1_0659.0, 11) prev_result.id=4192550
                      2005-05-09 14:27:05 [PID=26946] [debug ] est cpu dur 30069.284065; running_frac 0.930656; rsf 0.500000; est 64619.523091
                      2005-05-09 14:27:05 [PID=26946] [debug ] [HOST#61874] Sending app_version einstein windows_intelx86 479
                      2005-05-09 14:27:05 [PID=26946] [debug ] [HOST#61874] Already has file H1_0659.0
                      2005-05-09 14:27:05 [PID=26946] [debug ] [HOST#61874] reducing disk needed for WU by 14736000 bytes (length of H1_0659.0)
                      2005-05-09 14:27:05 [PID=26946] [debug ] est cpu dur 30069.284065; running_frac 0.930656; rsf 0.500000; est 64619.523091
                      2005-05-09 14:27:05 [PID=26946] [normal ] [HOST#61874] Sending [RESULT#4192560 H1_0659.0__0659.1_0.1_T03_Fin1_0] (fills 64619.52 seconds)
                      2005-05-09 14:27:05 [PID=26946] [debug ] in_send_results_for_file(H1_0659.0, 12) prev_result.id=4192560
                      2005-05-09 14:27:05 [PID=26946] [debug ] touched ../locality_scheduling/need_work/H1_0659.0: need work for file H1_0659.0
                      2005-05-09 14:27:05 [PID=26946] [debug ] make_more_work_for_file(H1_0659.0, 12)=0
                      2005-05-09 14:27:15 [PID=26946] [debug ] in_send_results_for_file(H1_0659.0, 13) prev_result.id=4192560
                      2005-05-09 14:27:15 [PID=26946] [debug ] est cpu dur 30069.284065; running_frac 0.930656; rsf 0.500000; est 64619.523091
                      2005-05-09 14:27:15 [PID=26946] [debug ] [HOST#61874] Sending app_version einstein windows_intelx86 479
                      2005-05-09 14:27:15 [PID=26946] [debug ] [HOST#61874] Already has file H1_0659.0
                      2005-05-09 14:27:15 [PID=26946] [debug ] [HOST#61874] reducing disk needed for WU by 14736000 bytes (length of H1_0659.0)
                      2005-05-09 14:27:15 [PID=26946] [debug ] est cpu dur 30069.284065; running_frac 0.930656; rsf 0.500000; est 64619.523091
                      2005-05-09 14:27:15 [PID=26946] [normal ] [HOST#61874] Sending [RESULT#4192571 H1_0659.0__0659.2_0.1_T03_Fin1_0] (fills 64619.52 seconds)
                      2005-05-09 14:27:15 [PID=26946] [normal ] [HOST#61874] Sent 8 results [scheduler ran 61 seconds]
                      2005-05-09 14:27:51 [PID=27170] [debug ] REQUEST_METHOD=POST CONTENT_TYPE=application/octet-stream HTTP_ACCEPT= HTTP_USER_AGENT=BOINC client (windows_intelx86 4.26)
                      2005-05-09 14:27:51 [PID=27170] [debug ] CONTENT_LENGTH=8743 from X.X.X.X
                      2005-05-09 14:27:57 [PID=27170] [normal ] Handling request: IP X.X.X.X, auth XXX, host 61874, platform windows_intelx86, version 4.26
                      2005-05-09 14:27:57 [PID=27170] [normal ] OS version Microsoft Windows XP Professional Edition, Service Pack 2, (05.01.2600.00)
                      2005-05-09 14:27:57 [PID=27170] [debug ] Request [HOST#61874] Database [HOST#61874] Request [RPC#92] Database [RPC#84]
                      2005-05-09 14:27:57 [PID=27170] [normal ] Processing request from [USER#167] [HOST#61874] [IP X.X.X.X] [RPC#92] core client version 4.26
                      2005-05-09 14:27:57 [PID=27170] [normal ] [HOST#61874] [RESULT#3911567 H1_0723.4__0723.5_0.1_T15_Run2_1] got result
                      2005-05-09 14:27:57 [PID=27170] [CRITICAL] [HOST#61874] [RESULT#3911567 H1_0723.4__0723.5_0.1_T15_Run2_1] got result twice
                      2005-05-09 14:27:57 [PID=27170] [normal ] [HOST#61874] [RESULT#3915377 H1_0723.4__0723.8_0.1_T15_Run2_2] got result
                      2005-05-09 14:27:57 [PID=27170] [CRITICAL] [HOST#61874] [RESULT#3915377 H1_0723.4__0723.8_0.1_T15_Run2_2] got result twice
                      2005-05-09 14:27:57 [PID=27170] [normal ] [HOST#61874] [RESULT#3917535 H1_0723.4__0723.9_0.1_T15_Run2_1] got result
                      2005-05-09 14:27:57 [PID=27170] [debug ] cpu 42579.468750 cpcs 0.001458, cc 62.085913
                      2005-05-09 14:27:57 [PID=27170] [debug ] [RESULT#3917535 H1_0723.4__0723.9_0.1_T15_Run2_1]: setting outcome SUCCESS
                      2005-05-09 14:27:57 [PID=27170] [normal ] [HOST#61874] [RESULT#3918538 H1_0723.4__0723.5_0.1_T16_Run2_1] got result
                      2005-05-09 14:27:57 [PID=27170] [debug ] cpu 42031.906250 cpcs 0.001458, cc 61.287502
                      2005-05-09 14:27:57 [PID=27170] [debug ] [RESULT#3918538 H1_0723.4__0723.5_0.1_T16_Run2_1]: setting outcome SUCCESS
                      2005-05-09 14:27:57 [PID=27170] [normal ] [HOST#61874] [RESULT#3924126 H1_0723.4__0723.8_0.1_T16_Run2_3] got result
                      2005-05-09 14:27:57 [PID=27170] [debug ] cpu 42833.687500 cpcs 0.001458, cc 62.456595
                      2005-05-09 14:27:57 [PID=27170] [debug ] [RESULT#3924126 H1_0723.4__0723.8_0.1_T16_Run2_3]: setting outcome SUCCESS
                      2005-05-09 14:27:57 [PID=27170] [normal ] [HOST#61874] [RESULT#3983822 H1_0723.4__0723.8_0.1_T05_Run2_5] got result
                      2005-05-09 14:27:57 [PID=27170] [debug ] cpu 42275.000000 cpcs 0.001458, cc 61.641962
                      2005-05-09 14:27:57 [PID=27170] [debug ] [RESULT#3983822 H1_0723.4__0723.8_0.1_T05_Run2_5]: setting outcome SUCCESS
                      2005-05-09 14:27:57 [PID=27170] [normal ] [HOST#61874] got request for 518400.000000 seconds of work; available disk 14.636548 GB
                      2005-05-09 14:27:57 [PID=27170] [debug ] [HOST#61874]: has file H1_0659.0
                      2005-05-09 14:27:57 [PID=27170] [debug ] in_send_results_for_file(H1_0659.0, 0) prev_result.id=4192571
                      2005-05-09 14:27:57 [PID=27170] [debug ] touched ../locality_scheduling/need_work/H1_0659.0: need work for file H1_0659.0
                      2005-05-09 14:27:57 [PID=27170] [debug ] make_more_work_for_file(H1_0659.0, 0)=0
                      2005-05-09 14:28:07 [PID=27170] [debug ] in_send_results_for_file(H1_0659.0, 1) prev_result.id=4192571
                      2005-05-09 14:28:07 [PID=27170] [debug ] Sorted list of URLs follows [host timezone: UTC+7200]
                      2005-05-09 14:28:07 [PID=27170] [debug ] zone=+03600 url=http://einstein.aei.mpg.de
                      2005-05-09 14:28:07 [PID=27170] [debug ] zone=+00000 url=http://einstein.astro.gla.ac.uk
                      2005-05-09 14:28:07 [PID=27170] [debug ] zone=-18000 url=http://einstein.aset.psu.edu
                      2005-05-09 14:28:07 [PID=27170] [debug ] zone=-18000 url=http://morel.mit.edu
                      2005-05-09 14:28:07 [PID=27170] [debug ] zone=-21600 url=http://einstein.phys.uwm.edu
                      2005-05-09 14:28:07 [PID=27170] [debug ] [HOST#61874] Sending app_version einstein windows_intelx86 479
                      2005-05-09 14:28:07 [PID=27170] [debug ] [HOST#61874] Already has file H1_0659.0
                      2005-05-09 14:28:07 [PID=27170] [debug ] [HOST#61874] reducing disk needed for WU by 14736000 bytes (length of H1_0659.0)
                      2005-05-09 14:28:07 [PID=27170] [debug ] est cpu dur 30069.284065; running_frac 0.930659; rsf 0.500000; est 64619.320680
                      2005-05-09 14:28:07 [PID=27170] [normal ] [HOST#61874] Sending [RESULT#4192591 H1_0659.0__0659.3_0.1_T03_Fin1_0] (fills 64619.32 seconds)
                      2005-05-09 14:28:07 [PID=27170] [debug ] in_send_results_for_file(H1_0659.0, 2) prev_result.id=4192591
                      2005-05-09 14:28:07 [PID=27170] [debug ] touched ../locality_scheduling/need_work/H1_0659.0: need work for file H1_0659.0
                      2005-05-09 14:28:07 [PID=27170] [debug ] make_more_work_for_file(H1_0659.0, 2)=0
                      2005-05-09 14:28:17 [PID=27170] [debug ] in_send_results_for_file(H1_0659.0, 3) prev_result.id=4192591
                      2005-05-09 14:28:17 [PID=27170] [debug ] est cpu dur 30069.284065; running_frac 0.930659; rsf 0.500000; est 64619.320680
                      2005-05-09 14:28:17 [PID=27170] [debug ] [HOST#61874] Sending app_version einstein windows_intelx86 479
                      2005-05-09 14:28:17 [PID=27170] [debug ] [HOST#61874] Already has file H1_0659.0
                      2005-05-09 14:28:17 [PID=27170] [debug ] [HOST#61874] reducing disk needed for WU by 14736000 bytes (length of H1_0659.0)
                      2005-05-09 14:28:17 [PID=27170] [debug ] est cpu dur 30069.284065; running_frac 0.930659; rsf 0.500000; est 64619.320680
                      2005-05-09 14:28:17 [PID=27170] [normal ] [HOST#61874] Sending [RESULT#4192595 H1_0659.0__0659.4_0.1_T03_Fin1_0] (fills 64619.32 seconds)
                      2005-05-09 14:28:17 [PID=27170] [debug ] in_send_results_for_file(H1_0659.0, 4) prev_result.id=4192595
                      2005-05-09 14:28:17 [PID=27170] [debug ] touched ../locality_scheduling/need_work/H1_0659.0: need work for file H1_0659.0
                      2005-05-09 14:28:17 [PID=27170] [debug ] make_more_work_for_file(H1_0659.0, 4)=0
                      2005-05-09 14:28:27 [PID=27170] [debug ] in_send_results_for_file(H1_0659.0, 5) prev_result.id=4192595
                      2005-05-09 14:28:27 [PID=27170] [debug ] est cpu dur 30069.284065; running_frac 0.930659; rsf 0.500000; est 64619.320680
                      2005-05-09 14:28:27 [PID=27170] [debug ] [HOST#61874] Sending app_version einstein windows_intelx86 479
                      2005-05-09 14:28:27 [PID=27170] [debug ] [HOST#61874] Already has file H1_0659.0
                      2005-05-09 14:28:27 [PID=27170] [debug ] [HOST#61874] reducing disk needed for WU by 14736000 bytes (length of H1_0659.0)
                      2005-05-09 14:28:27 [PID=27170] [debug ] est cpu dur 30069.284065; running_frac 0.930659; rsf 0.500000; est 64619.320680
                      2005-05-09 14:28:27 [PID=27170] [normal ] [HOST#61874] Sending [RESULT#4192599 H1_0659.0__0659.0_0.1_T04_Fin1_0] (fills 64619.32 seconds)
                      2005-05-09 14:28:27 [PID=27170] [debug ] in_send_results_for_file(H1_0659.0, 6) prev_result.id=4192599
                      2005-05-09 14:28:27 [PID=27170] [debug ] touched ../locality_scheduling/need_work/H1_0659.0: need work for file H1_0659.0
                      2005-05-09 14:28:27 [PID=27170] [debug ] make_more_work_for_file(H1_0659.0, 6)=0
                      2005-05-09 14:28:37 [PID=27170] [debug ] in_send_results_for_file(H1_0659.0, 7) prev_result.id=4192599
                      2005-05-09 14:28:37 [PID=27170] [debug ] est cpu dur 30069.284065; running_frac 0.930659; rsf 0.500000; est 64619.320680
                      2005-05-09 14:28:37 [PID=27170] [debug ] [HOST#61874] Sending app_version einstein windows_intelx86 479
                      2005-05-09 14:28:37 [PID=27170] [debug ] [HOST#61874] Already has file H1_0659.0
                      2005-05-09 14:28:37 [PID=27170] [debug ] [HOST#61874] reducing disk needed for WU by 14736000 bytes (length of H1_0659.0)
                      2005-05-09 14:28:37 [PID=27170] [debug ] est cpu dur 30069.284065; running_frac 0.930659; rsf 0.500000; est 64619.320680
                      2005-05-09 14:28:37 [PID=27170] [normal ] [HOST#61874] Sending [RESULT#4192607 H1_0659.0__0659.1_0.1_T04_Fin1_0] (fills 64619.32 seconds)
                      2005-05-09 14:28:37 [PID=27170] [debug ] in_send_results_for_file(H1_0659.0, 8) prev_result.id=4192607
                      2005-05-09 14:28:37 [PID=27170] [debug ] touched ../locality_scheduling/need_work/H1_0659.0: need work for file H1_0659.0
                      2005-05-09 14:28:37 [PID=27170] [debug ] make_more_work_for_file(H1_0659.0, 8)=0
                      2005-05-09 14:28:47 [PID=27170] [debug ] in_send_results_for_file(H1_0659.0, 9) prev_result.id=4192607
                      2005-05-09 14:28:47 [PID=27170] [debug ] est cpu dur 30069.284065; running_frac 0.930659; rsf 0.500000; est 64619.320680
                      2005-05-09 14:28:47 [PID=27170] [debug ] [HOST#61874] Sending app_version einstein windows_intelx86 479
                      2005-05-09 14:28:47 [PID=27170] [debug ] [HOST#61874] Already has file H1_0659.0
                      2005-05-09 14:28:47 [PID=27170] [debug ] [HOST#61874] reducing disk needed for WU by 14736000 bytes (length of H1_0659.0)
                      2005-05-09 14:28:47 [PID=27170] [debug ] est cpu dur 30069.284065; running_frac 0.930659; rsf 0.500000; est 64619.320680
                      2005-05-09 14:28:47 [PID=27170] [normal ] [HOST#61874] Sending [RESULT#4192623 H1_0659.0__0659.2_0.1_T04_Fin1_0] (fills 64619.32 seconds)
                      2005-05-09 14:28:47 [PID=27170] [debug ] in_send_results_for_file(H1_0659.0, 10) prev_result.id=4192623
                      2005-05-09 14:28:47 [PID=27170] [debug ] touched ../locality_scheduling/need_work/H1_0659.0: need work for file H1_0659.0
                      2005-05-09 14:28:47 [PID=27170] [debug ] make_more_work_for_file(H1_0659.0, 10)=0
                      2005-05-09 14:28:57 [PID=27170] [debug ] in_send_results_for_file(H1_0659.0, 11) prev_result.id=4192623
                      2005-05-09 14:28:57 [PID=27170] [debug ] est cpu dur 30069.284065; running_frac 0.930659; rsf 0.500000; est 64619.320680
                      2005-05-09 14:28:57 [PID=27170] [debug ] [HOST#61874] Sending app_version einstein windows_intelx86 479
                      2005-05-09 14:28:57 [PID=27170] [debug ] [HOST#61874] Already has file H1_0659.0
                      2005-05-09 14:28:57 [PID=27170] [debug ] [HOST#61874] reducing disk needed for WU by 14736000 bytes (length of H1_0659.0)
                      2005-05-09 14:28:57 [PID=27170] [debug ] est cpu dur 30069.284065; running_frac 0.930659; rsf 0.500000; est 64619.320680
                      2005-05-09 14:28:57 [PID=27170] [normal ] [HOST#61874] Sending [RESULT#4192631 H1_0659.0__0659.3_0.1_T04_Fin1_0] (fills 64619.32 seconds)
                      2005-05-09 14:28:57 [PID=27170] [debug ] in_send_results_for_file(H1_0659.0, 12) prev_result.id=4192631
                      2005-05-09 14:28:57 [PID=27170] [debug ] touched ../locality_scheduling/need_work/H1_0659.0: need work for file H1_0659.0
                      2005-05-09 14:28:57 [PID=27170] [debug ] make_more_work_for_file(H1_0659.0, 12)=0
                      2005-05-09 14:29:07 [PID=27170] [debug ] in_send_results_for_file(H1_0659.0, 13) prev_result.id=4192631
                      2005-05-09 14:29:07 [PID=27170] [debug ] est cpu dur 30069.284065; running_frac 0.930659; rsf 0.500000; est 64619.320680
                      2005-05-09 14:29:07 [PID=27170] [debug ] [HOST#61874] Sending app_version einstein windows_intelx86 479
                      2005-05-09 14:29:07 [PID=27170] [debug ] [HOST#61874] Already has file H1_0659.0
                      2005-05-09 14:29:07 [PID=27170] [debug ] [HOST#61874] reducing disk needed for WU by 14736000 bytes (length of H1_0659.0)
                      2005-05-09 14:29:07 [PID=27170] [debug ] est cpu dur 30069.284065; running_frac 0.930659; rsf 0.500000; est 64619.320680
                      2005-05-09 14:29:07 [PID=27170] [normal ] [HOST#61874] Sending [RESULT#4192639 H1_0659.0__0659.4_0.1_T04_Fin1_0] (fills 64619.32 seconds)
                      2005-05-09 14:29:07 [PID=27170] [debug ] in_send_results_for_file(H1_0659.0, 14) prev_result.id=4192639
                      2005-05-09 14:29:07 [PID=27170] [debug ] touched ../locality_scheduling/need_work/H1_0659.0: need work for file H1_0659.0
                      2005-05-09 14:29:07 [PID=27170] [debug ] make_more_work_for_file(H1_0659.0, 14)=0
                      2005-05-09 14:29:17 [PID=27170] [debug ] in_send_results_for_file(H1_0659.0, 15) prev_result.id=4192639
                      2005-05-09 14:29:17 [PID=27170] [debug ] est cpu dur 30069.284065; running_frac 0.930659; rsf 0.500000; est 64619.320680
                      2005-05-09 14:29:17 [PID=27170] [debug ] [HOST#61874] Sending app_version einstein windows_intelx86 479
                      2005-05-09 14:29:17 [PID=27170] [debug ] [HOST#61874] Already has file H1_0659.0
                      2005-05-09 14:29:17 [PID=27170] [debug ] [HOST#61874] reducing disk needed for WU by 14736000 bytes (length of H1_0659.0)
                      2005-05-09 14:29:17 [PID=27170] [debug ] est cpu dur 30069.284065; running_frac 0.930659; rsf 0.500000; est 64619.320680
                      2005-05-09 14:29:17 [PID=27170] [normal ] [HOST#61874] Sending [RESULT#4192648 H1_0659.0__0659.0_0.1_T05_Fin1_0] (fills 64619.32 seconds)
                      2005-05-09 14:29:17 [PID=27170] [normal ] [HOST#61874] Sent 8 results [scheduler ran 86 seconds]
                      2005-05-09 14:29:34 [PID=27358] [debug ] REQUEST_METHOD=POST CONTENT_TYPE=application/octet-stream HTTP_ACCEPT= HTTP_USER_AGENT=BOINC client (windows_intelx86 4.26)
                      2005-05-09 14:29:34 [PID=27358] [debug ] CONTENT_LENGTH=11593 from X.X.X.X
                      2005-05-09 14:29:47 [PID=27358] [normal ] Handling request: IP X.X.X.X, auth XXX, host 61874, platform windows_intelx86, version 4.26
                      2005-05-09 14:29:47 [PID=27358] [normal ] OS version Microsoft Windows XP Professional Edition, Service Pack 2, (05.01.2600.00)
                      2005-05-09 14:29:47 [PID=27358] [debug ] Request [HOST#61874] Database [HOST#61874] Request [RPC#93] Database [RPC#84]
                      2005-05-09 14:29:47 [PID=27358] [normal ] Processing request from [USER#167] [HOST#61874] [IP X.X.X.X] [RPC#93] core client version 4.26
                      2005-05-09 14:29:47 [PID=27358] [normal ] [HOST#61874] [RESULT#3911567 H1_0723.4__0723.5_0.1_T15_Run2_1] got result
                      2005-05-09 14:29:47 [PID=27358] [CRITICAL] [HOST#61874] [RESULT#3911567 H1_0723.4__0723.5_0.1_T15_Run2_1] got result twice
                      2005-05-09 14:29:47 [PID=27358] [normal ] [HOST#61874] [RESULT#3915377 H1_0723.4__0723.8_0.1_T15_Run2_2] got result
                      2005-05-09 14:29:47 [PID=27358] [CRITICAL] [HOST#61874] [RESULT#3915377 H1_0723.4__0723.8_0.1_T15_Run2_2] got result twice
                      2005-05-09 14:29:47 [PID=27358] [normal ] [HOST#61874] [RESULT#3917535 H1_0723.4__0723.9_0.1_T15_Run2_1] got result
                      2005-05-09 14:29:47 [PID=27358] [CRITICAL] [HOST#61874] [RESULT#3917535 H1_0723.4__0723.9_0.1_T15_Run2_1] got result twice
                      2005-05-09 14:29:47 [PID=27358] [normal ] [HOST#61874] [RESULT#3918538 H1_0723.4__0723.5_0.1_T16_Run2_1] got result
                      2005-05-09 14:29:47 [PID=27358] [CRITICAL] [HOST#61874] [RESULT#3918538 H1_0723.4__0723.5_0.1_T16_Run2_1] got result twice
                      2005-05-09 14:29:47 [PID=27358] [normal ] [HOST#61874] [RESULT#3924126 H1_0723.4__0723.8_0.1_T16_Run2_3] got result
                      2005-05-09 14:29:47 [PID=27358] [CRITICAL] [HOST#61874] [RESULT#3924126 H1_0723.4__0723.8_0.1_T16_Run2_3] got result twice
                      2005-05-09 14:29:47 [PID=27358] [normal ] [HOST#61874] [RESULT#3983822 H1_0723.4__0723.8_0.1_T05_Run2_5] got result
                      2005-05-09 14:29:47 [PID=27358] [CRITICAL] [HOST#61874] [RESULT#3983822 H1_0723.4__0723.8_0.1_T05_Run2_5] got result twice
                      2005-05-09 14:29:47 [PID=27358] [normal ] [HOST#61874] [RESULT#4014138 H1_0723.4__0723.7_0.1_T15_Run2_4] got result
                      2005-05-09 14:29:47 [PID=27358] [debug ] cpu 41979.640625 cpcs 0.001458, cc 61.211293
                      2005-05-09 14:29:47 [PID=27358] [debug ] [RESULT#4014138 H1_0723.4__0723.7_0.1_T15_Run2_4]: setting outcome SUCCESS
                      2005-05-09 14:29:47 [PID=27358] [normal ] [HOST#61874] [RESULT#4001025 H1_0659.0__0659.4_0.1_T00_Fin1_2] got result
                      2005-05-09 14:29:47 [PID=27358] [debug ] cpu 42549.265625 cpcs 0.001458, cc 62.041874
                      2005-05-09 14:29:47 [PID=27358] [debug ] [RESULT#4001025 H1_0659.0__0659.4_0.1_T00_Fin1_2]: setting outcome SUCCESS
                      2005-05-09 14:29:47 [PID=27358] [normal ] [HOST#61874] [RESULT#4012049 H1_0659.0__0659.0_0.1_T01_Fin1_3] got result
                      2005-05-09 14:29:47 [PID=27358] [debug ] cpu 42615.671875 cpcs 0.001458, cc 62.138702
                      2005-05-09 14:29:47 [PID=27358] [debug ] [RESULT#4012049 H1_0659.0__0659.0_0.1_T01_Fin1_3]: setting outcome SUCCESS
                      2005-05-09 14:29:47 [PID=27358] [normal ] [HOST#61874] [RESULT#4012110 H1_0659.0__0659.1_0.1_T01_Fin1_2] got result
                      2005-05-09 14:29:47 [PID=27358] [debug ] cpu 42075.062500 cpcs 0.001458, cc 61.350429
                      2005-05-09 14:29:47 [PID=27358] [debug ] [RESULT#4012110 H1_0659.0__0659.1_0.1_T01_Fin1_2]: setting outcome SUCCESS
                      2005-05-09 14:29:47 [PID=27358] [normal ] [HOST#61874] got request for 518400.000000 seconds of work; available disk 14.636548 GB
                      2005-05-09 14:29:47 [PID=27358] [debug ] [HOST#61874]: has file H1_0659.0
                      2005-05-09 14:29:47 [PID=27358] [normal ] [HOST#61874] Sent 0 results [scheduler ran 13 seconds]
                      2005-05-09 14:29:47 [PID=27358] [normal ] Daily result quota exceeded for host 61874
                      2005-05-09 14:29:47 [PID=27358] [debug ] [HOST#61874] MSG(high) No work sent
                      2005-05-09 14:29:47 [PID=27358] [debug ] [HOST#61874] MSG(high) (reached daily quota of 16 results)
                      2005-05-09 14:29:47 [PID=27358] [normal ] sending delay request 3600.000000
                      [root@einstein tmp]#

                      Director, Einstein@Home

                      ralic
                      ralic
                      Joined: 8 Nov 04
                      Posts: 128
                      Credit: 695810
                      RAC: 0

                      Here is the relevant part of

                      10 May 2005 14:40:17 UTC
                      Message 11415 in response to message 11414
                      (moderation:
                        )

                        Here is the relevant part of the scheduler log. The basic problem seems to be that on your end the core client timed out after 36 seconds, whereas on the server, the scheduler continued to run for 61 seconds. I am making some inquiries with the BOINC developers to try and understand if the core client has a time-out which might have caused this broken connection and hence the lost WU.

                        Excellent. Thanks for the log snippet.
                        I suspect that there isn't a timeout in the client, or if there is, it's not as short as 36secs. There is a timeout in my proxy, which is around the 30sec mark. I'll need to up this setting, but the question is "how high?". I'll try 180secs for starters.

                        PS: you might want to use ntp or some other method to set the correct time on your machine. It's off by a few minutes.

                        You're 100% right, sorry about that... I'll have to look into it. :)

                        Well, it looks like my particular problem was easy enough to find, but the implications provide some food for thought.
                        It seems that a slow scheduler response, combined with a proxy time-out can cause quite a bit of grief for a project. How do we make BOINC more robust in this department? Perhaps the client needs to "acknowledge" a scheduler reply?

                        Thanks very much for the feedback. It's much appreciated.

                        Comment viewing options

                        Select your preferred way to display the comments and click "Save settings" to activate your changes.

                        Forums › Problems and Bug Reports