Zope 2

Bug #239636
Comment #3

Comment 3 for bug 239636

Revision history for this message

jswinner (jswinner) wrote on 2008-06-14:

No change with the recompile and the problem will not replicate in cadaver because it's not checking for a pre-existing resource like davfs is doing. The precheck can be optioned out in davfs2, but an apache bug comes with it.....

Here more detail:

So the the first PUT, Returns the 404, which makes since since the file does not exist.

JJun 13 20:37:59 office mount.davfs: Sending request headers: HEAD /file_store/files/Scanned/test/test12.pdf HTTP/1.1^M Host:192.168.0.120:9674^M User-Agent: davfs2/1.3.2 neon/0.27.2^M Connection: TE^M TE: trailers^M Authorization: xxxxxxxxxxxxxxxxxx^M ^M
Jun 13 20:37:59 office mount.davfs: Sending request-line and headers:
Jun 13 20:37:59 office mount.davfs: Connecting to 192.168.0.120
Jun 13 20:37:59 office mount.davfs: Request sent; retry is 0.
Jun 13 20:37:59 office mount.davfs: [status-line] < HTTP/1.1 404 Not Found^M
Jun 13 20:37:59 office mount.davfs: [hdr] Server: Zope/(Zope 2.10.6-final, python 2.4.4, linux2) ZServer/1.1 Plone/3.1.2^M

snipped log
Then the next cycle, note the borked status line

Jun 13 20:37:59 office mount.davfs: Running pre_send hooks
Jun 13 20:37:59 office mount.davfs: Sending request headers: PUT /file_store/files/Scanned/test/test12.pdf HTTP/1.1^M Host:192.168.0.120:9674^M User-Agent: davfs2/1.3.2 neon/0.27.2^M Connection: TE^M TE: trailers^M Content-Length: 221691^M Authorization: xxxxxxxxxxxxxxxxxx^M ^M
Jun 13 20:37:59 office mount.davfs: Sending request-line and headers:
Jun 13 20:37:59 office mount.davfs: Sending request body:
Jun 13 20:37:59 office mount.davfs: Request sent; retry is 1.
Jun 13 20:37:59 office mount.davfs: [status-line] < <!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN" "http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd">
Jun 13 20:37:59 office mount.davfs: Aborted request (0): Could not parse response status line
Jun 13 20:37:59 office mount.davfs: Closing connection.
Jun 13 20:37:59 office mount.davfs: Connection closed.
Jun 13 20:37:59 office mount.davfs: Request ends, status 0 class 0xx, error line: Could not parse response status line
Jun 13 20:37:59 office mount.davfs: Running destroy hooks.
Jun 13 20:37:59 office mount.davfs: Request ends.

Davfs retries every 10 sec, until it works finally, note the timestamp shift and the correct status response:

Jun 13 20:40:43 office mount.davfs: Sending request headers: HEAD /file_store/files/Scanned/test/test12.pdf HTTP/1.1^M Host: 192.168.0.120:9674^M User-Agent: davfs2/1.3.2 neon/0.27.2^M Connection: TE^M TE: trailers^M Authorization: xxxxxxxxxxxxxxxxxx^M ^M
Jun 13 20:40:43 office mount.davfs: Sending request-line and headers:
Jun 13 20:40:43 office mount.davfs: Connecting to 192.168.0.120
Jun 13 20:40:43 office mount.davfs: Request sent; retry is 0.
Jun 13 20:40:43 office mount.davfs: [status-line] < HTTP/1.1 200 OK^M
Jun 13 20:40:43 office mount.davfs: [hdr] Server: Zope/(Zope 2.10.6-final, python 2.4.4, linux2) ZServer/1.1 Plone/3.1.2^M
Jun 13 20:40:43 office mount.davfs: Header Name: [server], Value: [Zope/(Zope 2.10.6-final, python 2.4.4, linux2) ZServer/1.1 Plone/3.1.2]
Jun 13 20:40:43 office mount.davfs: [hdr] Date: Sat, 14 Jun 2008 03:40:44 GMT^M
Jun 13 20:40:43 office mount.davfs: Header Name: [date], Value: [Sat, 14 Jun 2008 03:40:44 GMT]
Jun 13 20:40:43 office mount.davfs: [hdr] Content-Length: 221691^M
Jun 13 20:40:43 office mount.davfs: Header Name: [content-length], Value: [221691]
Jun 13 20:40:43 office mount.davfs: [hdr] Accept-Ranges: none^M
Jun 13 20:40:43 office mount.davfs: Header Name: [accept-ranges], Value: [none]
Jun 13 20:40:43 office mount.davfs: [hdr] Last-Modified: Sat, 14 Jun 2008 03:40:35 GMT^M
Jun 13 20:40:43 office mount.davfs: Header Name: [last-modified], Value: [Sat, 14 Jun 2008 03:40:35 GMT]
Jun 13 20:40:43 office mount.davfs: [hdr] Etag: ts13414835.44^M
Jun 13 20:40:43 office mount.davfs: Header Name: [etag], Value: [ts13414835.44]
Jun 13 20:40:43 office mount.davfs: [hdr] Content-Type: application/pdf^M
Jun 13 20:40:43 office mount.davfs: Header Name: [content-type], Value: [application/pdf]
Jun 13 20:40:43 office mount.davfs: [hdr] ^M
Jun 13 20:40:43 office mount.davfs: End of headers.
Jun 13 20:40:43 office mount.davfs: Running post_headers hooks
Jun 13 20:40:43 office mount.davfs: Running post_send hooks
Jun 13 20:40:43 office mount.davfs: Request ends, status 200 class 2xx, error line: 200 OK
Jun 13 20:40:43 office mount.davfs: Running destroy hooks.
Jun 13 20:40:43 office mount.davfs: Request ends.

Here is the Z2.log for the time period

192.168.0.126 - jeff [13/Jun/2008:20:38:00 -0700] "HEAD /file_store/files/Scanned/test/test12.pdf HTTP/1.1" 404 19377 "" "davfs2/1.3.2 neon/0.27.2"
192.168.0.126 - jeff [13/Jun/2008:20:38:11 -0700] "HEAD /file_store/files/Scanned/test/test12.pdf HTTP/1.1" 404 19377 "" "davfs2/1.3.2 neon/0.27.2"
192.168.0.126 - jeff [13/Jun/2008:20:38:21 -0700] "HEAD /file_store/files/Scanned/test/test12.pdf HTTP/1.1" 404 19377 "" "davfs2/1.3.2 neon/0.27.2"
192.168.0.126 - jeff [13/Jun/2008:20:38:31 -0700] "HEAD /file_store/files/Scanned/test/test12.pdf HTTP/1.1" 404 19377 "" "davfs2/1.3.2 neon/0.27.2"
192.168.0.126 - jeff [13/Jun/2008:20:38:41 -0700] "HEAD /file_store/files/Scanned/test/test12.pdf HTTP/1.1" 404 19377 "" "davfs2/1.3.2 neon/0.27.2"
192.168.0.126 - jeff [13/Jun/2008:20:38:52 -0700] "HEAD /file_store/files/Scanned/test/test12.pdf HTTP/1.1" 404 19377 "" "davfs2/1.3.2 neon/0.27.2"
192.168.0.126 - jeff [13/Jun/2008:20:39:02 -0700] "HEAD /file_store/files/Scanned/test/test12.pdf HTTP/1.1" 404 19377 "" "davfs2/1.3.2 neon/0.27.2"
192.168.0.126 - jeff [13/Jun/2008:20:39:12 -0700] "HEAD /file_store/files/Scanned/test/test12.pdf HTTP/1.1" 404 19377 "" "davfs2/1.3.2 neon/0.27.2"
192.168.0.126 - jeff [13/Jun/2008:20:39:22 -0700] "HEAD /file_store/files/Scanned/test/test12.pdf HTTP/1.1" 404 19377 "" "davfs2/1.3.2 neon/0.27.2"
192.168.0.126 - jeff [13/Jun/2008:20:39:33 -0700] "HEAD /file_store/files/Scanned/test/test12.pdf HTTP/1.1" 404 19377 "" "davfs2/1.3.2 neon/0.27.2"
192.168.0.126 - jeff [13/Jun/2008:20:39:43 -0700] "HEAD /file_store/files/Scanned/test/test12.pdf HTTP/1.1" 404 19377 "" "davfs2/1.3.2 neon/0.27.2"
192.168.0.126 - jeff [13/Jun/2008:20:39:53 -0700] "HEAD /file_store/files/Scanned/test/test12.pdf HTTP/1.1" 404 19377 "" "davfs2/1.3.2 neon/0.27.2"
192.168.0.126 - jeff [13/Jun/2008:20:40:04 -0700] "HEAD /file_store/files/Scanned/test/test12.pdf HTTP/1.1" 404 19377 "" "davfs2/1.3.2 neon/0.27.2"
192.168.0.126 - jeff [13/Jun/2008:20:40:14 -0700] "HEAD /file_store/files/Scanned/test/test12.pdf HTTP/1.1" 404 19377 "" "davfs2/1.3.2 neon/0.27.2"
192.168.0.126 - jeff [13/Jun/2008:20:40:24 -0700] "HEAD /file_store/files/Scanned/test/test12.pdf HTTP/1.1" 404 19377 "" "davfs2/1.3.2 neon/0.27.2"
192.168.0.126 - jeff [13/Jun/2008:20:40:34 -0700] "HEAD /file_store/files/Scanned/test/test12.pdf HTTP/1.1" 404 19377 "" "davfs2/1.3.2 neon/0.27.2"
192.168.0.126 - jeff [13/Jun/2008:20:40:35 -0700] "PUT /file_store/files/Scanned/test/test12.pdf HTTP/1.1" 201 0 "" "davfs2/1.3.2 neon/0.27.2"
192.168.0.126 - jeff [13/Jun/2008:20:40:44 -0700] "HEAD /file_store/files/Scanned/test/test12.pdf HTTP/1.1" 200 279 "" "davfs2/1.3.2 neon/0.27.2"
192.168.0.126 - jeff [13/Jun/2008:20:40:45 -0700] "PUT /file_store/files/Scanned/test/test12.pdf HTTP/1.1" 204 165 "" "davfs2/1.3.2 neon/0.27.2"
192.168.0.126 - jeff [13/Jun/2008:20:40:45 -0700] "HEAD /file_store/files/Scanned/test/test12.pdf HTTP/1.1" 200 279 "" "davfs2/1.3.2 neon/0.27.2"

No change with the recompile and the problem will not replicate in cadaver because it's not checking for a pre-existing resource like davfs is doing.  The precheck can be optioned out in davfs2, but an apache bug comes with it.....

Here more detail:

So the the first PUT, Returns the 404, which makes since since the file does not exist.

JJun 13 20:37:59 office mount.davfs: Sending request headers: HEAD /file_store/files/Scanned/test/test12.pdf HTTP/1.1^M Host:192.168.0.120:9674^M User-Agent: davfs2/1.3.2 neon/0.27.2^M Connection: TE^M TE: trailers^M Authorization: xxxxxxxxxxxxxxxxxx^M ^M 
Jun 13 20:37:59 office mount.davfs: Sending request-line and headers: 
Jun 13 20:37:59 office mount.davfs: Connecting to 192.168.0.120 
Jun 13 20:37:59 office mount.davfs: Request sent; retry is 0. 
Jun 13 20:37:59 office mount.davfs: [status-line] < HTTP/1.1 404 Not Found^M 
Jun 13 20:37:59 office mount.davfs: [hdr] Server: Zope/(Zope 2.10.6-final, python 2.4.4, linux2) ZServer/1.1 Plone/3.1.2^M

snipped log
Then the next cycle, note the borked status line

Jun 13 20:37:59 office mount.davfs: Running pre_send hooks 
Jun 13 20:37:59 office mount.davfs: Sending request headers: PUT /file_store/files/Scanned/test/test12.pdf HTTP/1.1^M Host:192.168.0.120:9674^M User-Agent: davfs2/1.3.2 neon/0.27.2^M Connection: TE^M TE: trailers^M Content-Length: 221691^M Authorization: xxxxxxxxxxxxxxxxxx^M ^M 
Jun 13 20:37:59 office mount.davfs: Sending request-line and headers: 
Jun 13 20:37:59 office mount.davfs: Sending request body: 
Jun 13 20:37:59 office mount.davfs: Request sent; retry is 1. 
Jun 13 20:37:59 office mount.davfs: [status-line] < <!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN" "http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd"> 
Jun 13 20:37:59 office mount.davfs: Aborted request (0): Could not parse response status line 
Jun 13 20:37:59 office mount.davfs: Closing connection. 
Jun 13 20:37:59 office mount.davfs: Connection closed. 
Jun 13 20:37:59 office mount.davfs: Request ends, status 0 class 0xx, error line: Could not parse response status line 
Jun 13 20:37:59 office mount.davfs: Running destroy hooks. 
Jun 13 20:37:59 office mount.davfs: Request ends.

Davfs retries every 10 sec, until it works finally, note the timestamp shift and the correct status response:

Jun 13 20:40:43 office mount.davfs: Sending request headers: HEAD /file_store/files/Scanned/test/test12.pdf HTTP/1.1^M Host: 192.168.0.120:9674^M User-Agent: davfs2/1.3.2 neon/0.27.2^M Connection: TE^M TE: trailers^M Authorization: xxxxxxxxxxxxxxxxxx^M ^M 
Jun 13 20:40:43 office mount.davfs: Sending request-line and headers: 
Jun 13 20:40:43 office mount.davfs: Connecting to 192.168.0.120 
Jun 13 20:40:43 office mount.davfs: Request sent; retry is 0. 
Jun 13 20:40:43 office mount.davfs: [status-line] < HTTP/1.1 200 OK^M 
Jun 13 20:40:43 office mount.davfs: [hdr] Server: Zope/(Zope 2.10.6-final, python 2.4.4, linux2) ZServer/1.1 Plone/3.1.2^M 
Jun 13 20:40:43 office mount.davfs: Header Name: [server], Value: [Zope/(Zope 2.10.6-final, python 2.4.4, linux2) ZServer/1.1 Plone/3.1.2] 
Jun 13 20:40:43 office mount.davfs: [hdr] Date: Sat, 14 Jun 2008 03:40:44 GMT^M 
Jun 13 20:40:43 office mount.davfs: Header Name: [date], Value: [Sat, 14 Jun 2008 03:40:44 GMT] 
Jun 13 20:40:43 office mount.davfs: [hdr] Content-Length: 221691^M 
Jun 13 20:40:43 office mount.davfs: Header Name: [content-length], Value: [221691] 
Jun 13 20:40:43 office mount.davfs: [hdr] Accept-Ranges: none^M 
Jun 13 20:40:43 office mount.davfs: Header Name: [accept-ranges], Value: [none] 
Jun 13 20:40:43 office mount.davfs: [hdr] Last-Modified: Sat, 14 Jun 2008 03:40:35 GMT^M 
Jun 13 20:40:43 office mount.davfs: Header Name: [last-modified], Value: [Sat, 14 Jun 2008 03:40:35 GMT] 
Jun 13 20:40:43 office mount.davfs: [hdr] Etag: ts13414835.44^M 
Jun 13 20:40:43 office mount.davfs: Header Name: [etag], Value: [ts13414835.44] 
Jun 13 20:40:43 office mount.davfs: [hdr] Content-Type: application/pdf^M 
Jun 13 20:40:43 office mount.davfs: Header Name: [content-type], Value: [application/pdf] 
Jun 13 20:40:43 office mount.davfs: [hdr] ^M 
Jun 13 20:40:43 office mount.davfs: End of headers. 
Jun 13 20:40:43 office mount.davfs: Running post_headers hooks 
Jun 13 20:40:43 office mount.davfs: Running post_send hooks 
Jun 13 20:40:43 office mount.davfs: Request ends, status 200 class 2xx, error line: 200 OK 
Jun 13 20:40:43 office mount.davfs: Running destroy hooks. 
Jun 13 20:40:43 office mount.davfs: Request ends.

Here is the Z2.log for the time period