[Savannah-help-public] [gnu.org #767320] delays in updating web pages

[Peter Olson via RT]

> [ward - Mon Sep 17 14:01:37 2012]:
> 
> 
> Looks like the cvs checkout is not always completing before the new.py
> script times out. Sigh.

Here's the most recent example:

Sep 16 05:08:49 wildebeest savannah-cvs-commit: Request received...
Sep 16 05:08:49 wildebeest savannah-cvs-commit: type: www
Sep 16 05:08:49 wildebeest savannah-cvs-commit: project: www
Sep 16 05:08:49 wildebeest savannah-cvs-commit: /var/www: Beginning checkout
Sep 16 05:08:49 wildebeest savannah-cvs-commit: Working...
Sep 16 05:08:58 wildebeest savannah-cvs-commit: Request received...
Sep 16 05:08:58 wildebeest savannah-cvs-commit: type: www
Sep 16 05:08:58 wildebeest savannah-cvs-commit: project: www
Sep 16 05:08:58 wildebeest savannah-cvs-commit: /var/www: Beginning checkout
Sep 16 05:08:58 wildebeest savannah-cvs-commit: Working...
Sep 16 05:09:22 wildebeest savannah-cvs-commit: ? evaluation#012? 
new-savannah-project#012? savannah-checkouts#012? 
server/mwEmbed/.new.html5-hea#012? software/gcc
Sep 16 05:09:22 wildebeest savannah-cvs-commit: /var/www: checkout done

There are two requests and the second one worked but the first didn't.

Status code 500 returned:

140.186.70.72 - - [16/Sep/2012:05:08:49 -0400] "POST 
/new-savannah-project/new.py HTTP/1.1" 500 1711 "-" "curl/7.21.0 
(i486-pc-linux-gnu) 
libcurl/7.21.0 OpenSSL/0.9.8o zlib/1.2.3.4 libidn/1.15 libssh2/1.2.6"

Status code 200 returned:
140.186.70.72 - - [16/Sep/2012:05:08:58 -0400] "POST 
/new-savannah-project/new.py HTTP/1.1" 200 259 "-" "curl/7.21.0 
(i486-pc-linux-gnu) 
libcurl/7.21.0 OpenSSL/0.9.8o zlib/1.2.3.4 libidn/1.15 libssh2/1.2.6"

The 500 error is from an interrupted system call, as Ward noticed.  The request 
was received at 05:08:49 and terminated at 05:08:57, only 8 
seconds later.

Here's another example, showing a series of requests failing

Sep  4 00:00:15 wildebeest savannah-cvs-commit: Request received...
Sep  4 00:00:24 wildebeest savannah-cvs-commit: /var/www: checkout done
Sep  4 04:30:53 wildebeest savannah-cvs-commit: Request received...
Sep  4 04:31:42 wildebeest savannah-cvs-commit: Request received...
Sep  4 04:33:16 wildebeest savannah-cvs-commit: Request received...
Sep  4 04:34:29 wildebeest savannah-cvs-commit: Request received...
Sep  4 04:35:32 wildebeest savannah-cvs-commit: Request received...
Sep  4 04:41:50 wildebeest savannah-cvs-commit: /var/www: checkout done
Sep  4 04:52:41 wildebeest savannah-cvs-commit: Request received...
Sep  4 04:53:03 wildebeest savannah-cvs-commit: /var/www: checkout done

140.186.70.72 - - [04/Sep/2012:00:00:15 -0400] "POST 
/new-savannah-project/new.py HTTP/1.1" 200 278 "-" "curl/7.21.0 
(i486-pc-linux-gnu) 
libcurl/7.21.0 OpenSSL/0.9.8o zlib/1.2.3.4 libidn/1.15 libssh2/1.2.6"
140.186.70.72 - - [04/Sep/2012:04:30:53 -0400] "POST 
/new-savannah-project/new.py HTTP/1.1" 500 1720 "-" "curl/7.21.0 
(i486-pc-linux-gnu) 
libcurl/7.21.0 OpenSSL/0.9.8o zlib/1.2.3.4 libidn/1.15 libssh2/1.2.6"
140.186.70.72 - - [04/Sep/2012:04:31:42 -0400] "POST 
/new-savannah-project/new.py HTTP/1.1" 500 1720 "-" "curl/7.21.0 
(i486-pc-linux-gnu) 
libcurl/7.21.0 OpenSSL/0.9.8o zlib/1.2.3.4 libidn/1.15 libssh2/1.2.6"
140.186.70.72 - - [04/Sep/2012:04:33:16 -0400] "POST 
/new-savannah-project/new.py HTTP/1.1" 500 1719 "-" "curl/7.21.0 
(i486-pc-linux-gnu) 
libcurl/7.21.0 OpenSSL/0.9.8o zlib/1.2.3.4 libidn/1.15 libssh2/1.2.6"
140.186.70.72 - - [04/Sep/2012:04:34:29 -0400] "POST 
/new-savannah-project/new.py HTTP/1.1" 500 1720 "-" "curl/7.21.0 
(i486-pc-linux-gnu) 
libcurl/7.21.0 OpenSSL/0.9.8o zlib/1.2.3.4 libidn/1.15 libssh2/1.2.6"
140.186.70.72 - - [04/Sep/2012:04:35:32 -0400] "POST 
/new-savannah-project/new.py HTTP/1.1" 200 278 "-" "curl/7.21.0 
(i486-pc-linux-gnu) 
libcurl/7.21.0 OpenSSL/0.9.8o zlib/1.2.3.4 libidn/1.15 libssh2/1.2.6"

Here are the errors:

[Tue Sep 04 04:31:34 2012] [error] [client 140.186.70.72] IOError: [Errno 4] 
Interrupted system call
[Tue Sep 04 04:32:02 2012] [error] [client 140.186.70.72] IOError: [Errno 4] 
Interrupted system call
[Tue Sep 04 04:34:19 2012] [error] [client 140.186.70.72] IOError: [Errno 4] 
Interrupted system call
[Tue Sep 04 04:34:58 2012] [error] [client 140.186.70.72] IOError: [Errno 4] 
Interrupted system call

These times occurred 41, 20, 63, and 29 seconds after receipt of the 
corresponding requests (assuming that the times occurred in the same 
order as the requests, I'm not sure the log gives enough information).

For purpose of comparison, this is the distribution of processing times for all 
request since the beginning of 2012, divided into two groups, 
checkouts and other transactions:

first column, duration less than or equal in seconds
second column count
third column percentage of total

1       16       0.17
2       20       0.22
3       34       0.38
4       87       0.97
5       165      1.84
10      2230    24.99
15      2846    31.90
20      1272    14.25
30      1057    11.84
40      428      4.79
50      302      3.38
60      237      2.65
70      111      1.24
80      37       0.41
395     79       0.88

other histo, total 5058
1       1704    33.68
2       2122    41.95
3       518     10.24
4       192      3.79
5       98       1.93
10      210      4.15
15      83       1.64
20      47       0.92
30      38       0.75
40      18       0.35
50      12       0.23
70      10       0.19
132     6        0.11

So a timeout after 8 seconds is not acceptable.  One question to ask is whther 
the timeout occurs because of something at the requestor's 
end, or is it something in new.py or its host environment?

Peter Olson
FSF Senior Systems Administrator