Item5548: Twiki Hangs on Edit or Save of Long Entries

If I put enough content into a twiki node, I can no longer reliably save or edit it. I also cannot create a brand-new node with lots of content - I have to create it first, save it, re-edit it, and finally save it. I discovered this on my 4.2 install, and have subsequently verified that it exists in the sandbox here.

There are two problems I am encountering - When I click the "edit" button, to edit a Large node, the edit framework appears quickly, but the content window remains at "Please wait.... retreiving from server" for quite some time.

The second problem occurs on saving the same long page. After clicking the blue "save" button, firefox shows "Waiting for develop.twiki.org" but never progresses anywhere. From this point one has to navigate back to the Node, re-open for editing, and try saving again.

These two cases seem to occur more reliably (no pun intended,) if I authenticate AFTER clicking the "Edit" button.

There is a third outlying case, which I encountered while trying to setup a test case for the above; If I create a brand-new Topic, and paste in a gob of data, as one may find on the LitterTray page I link below, I am unable to save the page. Unlike the above two cases, this is independant of whether I had to login or not. (but obviously, I end up logged in, in order to create, edit & save.)

I provide Two test scenarios below. If one provides the Expected Result for you, please try it at least once more. I have verified these on more than one of: OS, Browser, Computer, ISP, and Twiki Version.

---

Test case #1

1. Close all your browser windows, so as to logout of develop.twiki.org
2. Navigate to this page: http://develop.twiki.org/~twiki4/cgi-bin/view/LitterTray/Item5548TestCase
3. Confirm that you are indeed logged OUT of twiki.
4. Click the 'Edit' button in the upper right.
5. Enter your Login Details, and login.
6. Make a minor edit (change a letter, or anything, but preserve the bulk.)
7. Click the Blue Save button.

Expected Result:

• Completing Step 7 returns you to the Viewing Mode of linked page.

Actual Result:
Either of:

• Between steps 5 & 6, WYSIWYG editor displays "Please wait.... retreiving from server" for an inordinate amoun t of time. Letting it wait for a long time, one will eventually get to the editor. Patience is required to verify, I usually give up waiting after 60 seconds.
• After step 7, page "hangs" or "stalls" without returning to View, and changes are not saved.

---

Test Case 2

1. Login to Twiki.org
2. Navigate to http://develop.twiki.org/~twiki4/cgi-bin/view/LitterTray/Item5548TestCase
3. Copy all text between the <lipsum>...</lipsum> tags
4. Navigate to http://develop.twiki.org/~twiki4/cgi-bin/view/Sandbox/WebHome
5. Create a new Topic, call it anything.
6. In the edit Box, paste the <lipsum> text
7. Click the Blue button marked "Save"

Expected Result:

• Page is Saved

Actual Result:

• Browser appears to initiate communication with twiki.org, but never completes the save process.

---

-- TWiki:Main/GavinMcDonald - 17 Apr 2008

I believe this is symptomatic of an ongoing problem we have had with this server, where sometimes things can take a really long time for no apparent reason. It has mainly been reported by users in Germany and Denmark, though i have seen it as well. Strongly suspect this is not specific to WysiwygPlugin, but would be happy to be proved wrong.

-- TWiki:Main.CrawfordCurrie - 18 Apr 2008

I've been beating on this all day today, and I can offer a little more insight into "what happens" though the "why" or "where" is still a little unclear:

I put some 'print STDERR's as the first & last lines in twiki/bin/edit twiki/bin/save and twiki/bin/rest. When these scripts run, they run fast. HOWEVER, they do not always run. From the apache logs, I gather that POSTing to either /save or /rest while unauthorized causes an approximately 90s blocking delay.

Here's a play-by-play with my slightly sanitized apache access_log:

First, I go to the page.

192.168.0.65 - - [16:43:22] "GET /twiki/bin/view/Sandbox/AnotherTestTopic HTTP/1.1" 200 "-"

then I click the edit button:

192.168.0.65 - - [16:43:39] "GET /twiki/bin/edit/Sandbox/AnotherTestTopic?t=1209080603 HTTP/1.1" 401 "http://host/twiki/bin/view/Sandbox/AnotherTestTopic"

Apache prompts for my login details, and I oblige. then my browser, (i think,) reissues the GET, but passes along my new credentials.

192.168.0.65 - GavinMcDonald [16:43:48] "GET /twiki/bin/edit/Sandbox/AnotherTestTopic?t=1209080603 HTTP/1.1" 200 "http://host/twiki/bin/view/Sandbox/AnotherTestTopic"

Now the wysiwyg editor frame appears, containing the red "please wait" message and I wait for ~90 seconds.

Suddenly the page contents finish loading, and the next two lines are logged simultaneously:

192.168.0.65 - - [16:43:50] "POST /twiki/bin/rest/WysiwygPlugin/tml2html HTTP/1.1" 401 "http://host/twiki/bin/edit/Sandbox/AnotherTestTopic?t=1209080603"

192.168.0.65 - GavinMcDonald [16:45:51] "POST /twiki/bin/rest/WysiwygPlugin/tml2html HTTP/1.1" 200 "http://host/twiki/bin/edit/Sandbox/AnotherTestTopic?t=1209080603"

Now weirder still, is the results from the aforementioned print statements, which wind up in the error_log:

[16:43:48] [client 192.168.0.65] EDIT: Script started at 16:43:48 2008, referer: http://host/twiki/bin/view/Sandbox/AnotherTestTopic
[16:43:48] [client 192.168.0.65] EDIT: Script ended at 16:43:48 2008, referer: http://host/twiki/bin/view/Sandbox/AnotherTestTopic
- 90 second PAUSE-
[16:45:51] [client 192.168.0.65] REST: Script started at 16:45:51 2008, referer: http://host/twiki/bin/edit/Sandbox/AnotherTestTopic?t=1209080603
[16:45:51] [client 192.168.0.65] REST: Script ended at 16:45:51 2008, referer: http://host/twiki/bin/edit/Sandbox/AnotherTestTopic?t=1209080603

This shows that despite 2 calls each, the scripts only run one time each. Matching the timestamps shows that only the authenticated requests cause script invocation. However, what this does not explain, is a) what kicks off the unauthenticated POST request to /rest and b) why apache blocks for ~90 seconds before processing the second request.

Given the 401 return code, I wonder if

Item4929: need to work out howto deal with access denied error in rest

is related to this problem?

-- TWiki:Main.GavinMcDonald - 25 Apr 2008

I'm pretty sure Item4929 is a red herring. I only use the REST handlers from WysiwygPlugin and they never raise access control violations; they have no need to, because all the information they use is provided to them in the POST request.

This is a useful debug. What interests me is that first apparently unauthenticated POST. The edit request has already been rejected at this point, and resubmitted with auth details as you described, so the browser has cached auth details for the domain. Here's the sequence of events as I read them from your info:

1. Uses clicks the 'edit' button in the browser
2. Browser raises an unauthenticated GET request
3. Apache 401's the request without ever going near TWiki
4. Browser prompts for login details, and reposts the edit request
5. Apache runs the (now authenticated) edit script on the server, which pushes a bunch of Javascript at the browser
6. Browser runs the Javascript. As part of that, browser raises a POST request to tml2html. This POST is seen as unauthenticated, despite being a request to an authenticated domain. The rest is irrelevant. The first question is, why is that POST request seen as unauthenticated? The edit script cannot be run until the browser is authenticated, and the edit script has to be run before that POST can be raised; therefore we know for certain that the browser is authenticated. I used the standard XmlHTTPRequest API to raise the POST, which is supposed to pass the cached authentication details with the request; indeed we know it does this correctly, because it runs the rest script, which requires authentication (I hope; check your Apache config).

I'm slightly concerned that debugging this using print statements and error logs is too hit-and-miss. Really you need to be looking at the transactions using ethereal (or wireshark, or a similar network protocol analyser).

BTW I cannot reproduce this behaviour using Firefox, IE or Safari

-- CrawfordCurrie - 25 Apr 2008

-- TWiki:Main.GavinMcDonald - 01 May 2008

It is unfortunate that you cannot reproduce this bug on your side, as I have an office full of people that can. Regardless, here's some more info, having had the benefit of a protocol sniffer...

The "delay" is definitely a 401 timeout. For whatever reason, both the /save and /edit scripts are being called without the appropriate authentication being passed along, and apache stalls waiting for a response to it's 401. once the 401 server request times out, the browser (or script?) resubmits it's request, with authentication this time, and everything proceeds immediately.

So arguably, (and hopefully provably,) the edit/save scripts are not properly retaining their authentication data for their first rest calls, nor are they 'handling' 401s from same.

In other words, the first pass through /edit after authentication kicks off an unauthenticated call to /rest. This call 401s, and as /edit does not deal with a 401'ing /rest, apache blocks waiting for an answer that never comes. Once apache gives up and closes the socket, /edit retries the rest call, this time WITH proper authentication, and everything continues. I'm new to the twiki code, but it looks like dissecting /edit is the next step in this debug.

-- TWiki:Main.GavinMcDonald - 01 May 2008

Whatever you debug make sure to separate what you see here on develop.twiki.org (d.t.o) and what you see on your own server.

On d.t.o I have been watching the Apache logs and when d.t.o acts up the request that never gets answered by Apache reaches apache up to 2 minutes later - long after the browser has timed out.

I have two ADSL lines with very different IP addressed and when I see this issue I can connect to the same d.t.o page and edit and save with no delay and see the connections instantly on the d.t.o apache log. This happens to me daily. We are many that experience this but not all of us experience it. It seems to be some routing problem. When I use my 83.91.41.235 line it often fails. When I use 62.243.208.118 I never see the problem. I also see the problem from work where I access through a gateway in Germany.

There is a bug report on this already but I am 100% convinced the issue is not in the TWiki code but some sick routing at our d.t.o host.

twiki.org may also time out at times but that is because of server load

Gavin I assume your last observations about 401 timeouts are observed on your own server, and then it is a quite different problem that deserves to be taken seriously.

Looking forward to seeing more analysis from your. But forget d.t.o. That is another problem

-- TWiki:Main.KennethLavrsen - 01 May 2008

I apologise, I should have been clearer - All of my debugging has been done against our local twiki, (v4.2). I have run the test cases against the live code on this twiki as well, and obtained the same behaviour, though less reliably.

And you are correct, the 401 timeouts are against our local twiki. Further to this, here are the results of yet another test, this time with wireshark listening;

No.     Time        Source                Destination           Protocol Info
     11 0.540637    192.168.0.38          192.168.0.35          HTTP     GET /twiki/bin/edit/Sandbox/TestPage?t=1209677566 HTTP/1.1

Internet Protocol, Src: 192.168.0.38 (192.168.0.38), Dst: 192.168.0.35 (192.168.0.35)
Hypertext Transfer Protocol
    GET /twiki/bin/edit/Sandbox/TestPage?t=1209677566 HTTP/1.1\r\n
    Host: hostname\r\n
    User-Agent: Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.8.1.6) Gecko/20070904 Firefox/2.0.0.6\r\n
    Accept: text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5\r\n
    Accept-Language: en-us,en;q=0.5\r\n
    Accept-Encoding: gzip,deflate\r\n
    Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7\r\n
    Keep-Alive: 300\r\n
    Connection: keep-alive\r\n
    Referer: http://hostname/twiki/bin/view/Sandbox/TestPage\r\n
    Cookie: TWIKISID=6244a989af97bf6ab494e2e26cf69232\r\n
    \r\n

No.     Time        Source                Destination           Protocol Info
     58 1.514014    192.168.0.35          192.168.0.38          HTTP     [TCP Retransmission] HTTP/1.1 401 Authorization Required (text/html)

Internet Protocol, Src: 192.168.0.35 (192.168.0.35), Dst: 192.168.0.38 (192.168.0.38)
Hypertext Transfer Protocol
    HTTP/1.1 401 Authorization Required\r\n
    Date: Thu, 01 May 2008 21:33:32 GMT\r\n
    Server: Apache/2.0.52 (Red Hat)\r\n
    WWW-Authenticate: Basic realm="Enter your WikiName: (First name and last name, no space, no dots, capitalized, e.g. JohnSmith). Cancel to register if you do not have one."\r\n
    Set-Cookie: TWIKISID=6244a989af97bf6ab494e2e26cf69232; path=/\r\n
    Content-Length: 32242
    Connection: close\r\n
    Content-Type: text/html; charset=iso-8859-1\r\n
    \r\n
Line-based text data: text/html
    <!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN" "http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd"><html xmlns="http://www.w3.org/1999/xhtml" xml:lang="en-us" lang="en-us">\n
    </body></html>

No.     Time        Source                Destination           Protocol Info
     67 4.964356    192.168.0.38          192.168.0.35          HTTP     GET /twiki/bin/edit/Sandbox/TestPage?t=1209677566 HTTP/1.1

Internet Protocol, Src: 192.168.0.38 (192.168.0.38), Dst: 192.168.0.35 (192.168.0.35)
Hypertext Transfer Protocol
    GET /twiki/bin/edit/Sandbox/TestPage?t=1209677566 HTTP/1.1\r\n
    Host: hostname\r\n
    User-Agent: Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.8.1.6) Gecko/20070904 Firefox/2.0.0.6\r\n
    Accept: text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5\r\n
    Accept-Language: en-us,en;q=0.5\r\n
    Accept-Encoding: gzip,deflate\r\n
    Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7\r\n
    Keep-Alive: 300\r\n
    Connection: keep-alive\r\n
    Referer: http://hostname/twiki/bin/view/Sandbox/TestPage\r\n
    Cookie: TWIKISID=6244a989af97bf6ab494e2e26cf69232\r\n
    Authorization: Basic R2F2aW5NY0RvbmFsZDppdzBqaW1h\r\n
    \r\n

No.     Time        Source                Destination           Protocol Info
    123 5.286750    192.168.0.35          192.168.0.38          HTTP     [TCP Out-Of-Order] HTTP/1.1 200 OK (text/html)

Internet Protocol, Src: 192.168.0.35 (192.168.0.35), Dst: 192.168.0.38 (192.168.0.38)
Hypertext Transfer Protocol
    HTTP/1.1 200 OK\r\n
    Date: Thu, 01 May 2008 21:33:36 GMT\r\n
    Server: Apache/2.0.52 (Red Hat)\r\n
    Expires: Fri, 02 May 2008 21:33:36 GMT\r\n
    Cache-control: max-age=86400\r\n
    Set-Cookie: TWIKISID=6244a989af97bf6ab494e2e26cf69232; path=/\r\n
    Last-Modified: Thu, 01 May 2008 21:33:36 GMT\r\n
    Content-Length: 38644
    Connection: close\r\n
    Content-Type: text/html; charset=iso-8859-1\r\n
    \r\n
Line-based text data: text/html
    <!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN" "http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd"><html xmlns="http://www.w3.org/1999/xhtml" xml:lang="en-us" lang="en-us">\n
    <head>\n
    </body></html>\n
    <p />\n
    <p />

No.     Time        Source                Destination           Protocol Info
    157 7.668847    192.168.0.38          192.168.0.35          HTTP     POST /twiki/bin/rest/WysiwygPlugin/tml2html HTTP/1.1 (application/x-www-form-urlencoded)

Internet Protocol, Src: 192.168.0.38 (192.168.0.38), Dst: 192.168.0.35 (192.168.0.35)
Hypertext Transfer Protocol
    POST /twiki/bin/rest/WysiwygPlugin/tml2html HTTP/1.1\r\n
    Host: hostname\r\n
    User-Agent: Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.8.1.6) Gecko/20070904 Firefox/2.0.0.6\r\n
    Accept: text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5\r\n
    Accept-Language: en-us,en;q=0.5\r\n
    Accept-Encoding: gzip,deflate\r\n
    Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7\r\n
    Keep-Alive: 300\r\n
    Connection: close\r\n
    Content-Type: application/x-www-form-urlencoded\r\n
    Referer: http://hostname/twiki/bin/edit/Sandbox/TestPage?t=1209677566\r\n
    Content-Length: 24584
    Cookie: TWIKISID=6244a989af97bf6ab494e2e26cf69232\r\n
    Pragma: no-cache\r\n
    Cache-Control: no-cache\r\n
    \r\n
Line-based text data: application/x-www-form-urlencoded
    nocache=1209674005704&topic=Sandbox.TestPage&text=192.168.0.65%2520-%2520GavinMcDonald%2520%255B24%2FApr%2F2008%253A12%253A06%253A33%2520-0700%255D%2520%2522GET%2520%2Ftwiki%2Fbin%2Fedit%2FSandbox%2FAnotherTestTopic%253Ft%253D1209063955%25

No.     Time        Source                Destination           Protocol Info
    218 127.679797  192.168.0.35          192.168.0.38          HTTP     [TCP Out-Of-Order] HTTP/1.1 401 Authorization Required (text/html)

Internet Protocol, Src: 192.168.0.35 (192.168.0.35), Dst: 192.168.0.38 (192.168.0.38)
Hypertext Transfer Protocol
    HTTP/1.1 401 Authorization Required\r\n
    Date: Thu, 01 May 2008 21:33:39 GMT\r\n
    Server: Apache/2.0.52 (Red Hat)\r\n
    WWW-Authenticate: Basic realm="Enter your WikiName: (First name and last name, no space, no dots, capitalized, e.g. JohnSmith). Cancel to register if you do not have one."\r\n
    Set-Cookie: TWIKISID=6244a989af97bf6ab494e2e26cf69232; path=/\r\n
    Content-Length: 33298
    Connection: close\r\n
    Content-Type: text/html; charset=iso-8859-1\r\n
    \r\n
Line-based text data: text/html
    <!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN" "http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd"><html xmlns="http://www.w3.org/1999/xhtml" xml:lang="en-us" lang="en-us">\n
    <head>\n
        </body></html>

No.     Time        Source                Destination           Protocol Info
    257 127.684629  192.168.0.38          192.168.0.35          HTTP     POST /twiki/bin/rest/WysiwygPlugin/tml2html HTTP/1.1 (application/x-www-form-urlencoded)

Internet Protocol, Src: 192.168.0.38 (192.168.0.38), Dst: 192.168.0.35 (192.168.0.35)
Hypertext Transfer Protocol
    POST /twiki/bin/rest/WysiwygPlugin/tml2html HTTP/1.1\r\n
    Host: hostname\r\n
    User-Agent: Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.8.1.6) Gecko/20070904 Firefox/2.0.0.6\r\n
    Accept: text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5\r\n
    Accept-Language: en-us,en;q=0.5\r\n
    Accept-Encoding: gzip,deflate\r\n
    Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7\r\n
    Keep-Alive: 300\r\n
    Connection: close\r\n
    Content-Type: application/x-www-form-urlencoded\r\n
    Referer: http://hostname/twiki/bin/edit/Sandbox/TestPage?t=1209677566\r\n
    Content-Length: 24584
    Cookie: TWIKISID=6244a989af97bf6ab494e2e26cf69232\r\n
    Pragma: no-cache, no-cache\r\n
    Cache-Control: no-cache, no-cache\r\n
    Authorization: Basic R2F2aW5NY0RvbmFsZDppdzBqaW1h\r\n
    \r\n
Line-based text data: application/x-www-form-urlencoded
    nocache=1209674005704&topic=Sandbox.TestPage&text=192.168.0.65%2520-%2520GavinMcDonald%2520%255B24%2FApr%2F2008%253A12%253A06%253A33%2520-0700%255D%2520%2522GET%2520%2Ftwiki%2Fbin%2Fedit%2FSandbox%2FAnotherTestTopic%253Ft%253D1209063955%25

No.     Time        Source                Destination           Protocol Info
    280 127.903774  192.168.0.35          192.168.0.38          HTTP     HTTP/1.1 200 OK (text/html)

Internet Protocol, Src: 192.168.0.35 (192.168.0.35), Dst: 192.168.0.38 (192.168.0.38)
Hypertext Transfer Protocol
    HTTP/1.1 200 OK\r\n
    Date: Thu, 01 May 2008 21:35:39 GMT\r\n
    Server: Apache/2.0.52 (Red Hat)\r\n
    Set-Cookie: TWIKISID=6244a989af97bf6ab494e2e26cf69232; path=/\r\n
    Content-Length: 15010
    Connection: close\r\n
    Content-Type: text/html; charset=iso-8859-1\r\n
    \r\n
Line-based text data: text/html
    < !--WYSIWYG content - do not remove this comment, and never use this identical text in your topics-- ><p>\n
 

I edited the above for brevity, (removed most of the HTML, and some ethernet details,) but these represent a "delayed" edit transaction with our local twiki server.

Pay specific attention to packet 157 vs packet 257. Packet 157 is a POST to /rest/WysiwygPlugin and it carries NO authentication data. packet 218 is the timed-out 401 response, and finally 257 is the resent POST, but this time, authentication headers are included.

As you said above, Kenneth, it is a quite different problem that deserves to be taken seriously. From a rough read of the code, my first question is if the block of code from lines 2219 to 2251 in twiki/lib/TWiki.pm may be responsible, as "if the set of tags expanded is extended, then the impact has to be considered..." but the same comment does claim this to be quite safe, so I cannot say with any certainty.

Barring a problem with the tags, the next spot worth looking at is in twiki/pub/TWiki/TinyMCEPlugin/twiki_tiny_src.js, lines 57 thru 101. I note that from 88 to 97, there is this little gem of ajax:

             // Callback for XMLHttpRequest
            // only if TWikiTiny.request.req shows "complete"
            if (TWikiTiny.request.req.readyState == 4) {
                // only if "OK"
                if (TWikiTiny.request.req.status == 200) {
                    onReply();
                } else {
                    onFail();
                }
            }
        };

Maybe a 401 handler here is in order?

-- GavinMcDonald - 01 May 2008

A 401handler should not be required. XmlHttpRequest is supposed pass on auth details, and is also supposed to handle 401 transparently - see http://dev.w3.org/cvsweb/2006/webapi/XMLHttpRequest/Overview.html?rev=1.16 - indeed, any number of testcases can demonstrate that it does.

Just to check sanity, did you edit a lot of requests out of the script above? I'm puzzled why I am not seeing requests that should have been raised by the loading of the 'edit' javascript, such as the CSS and JS files. Or perhaps they are being satisified from the browser cache? I'd like to see at least one intermediate request, because it should show if this "loss of authorization" problem is common to other requests (besides those sent via XmlHttpRequest)

So, to detail. Editing your request dump even more aggressively:

1. Time: 0.540637 192.168.0.38 to 192.168.0.35 GET /twiki/bin/edit/Sandbox/TestPage
2. Time: 1.514014 192.168.0.35 to 192.168.0.38 401 Authorization Required
3. Time: 4.964356 192.168.0.38 to 192.168.0.35 GET /twiki/bin/edit/Sandbox/TestPage with auth details
4. Time: 5.286750 192.168.0.35 to 192.168.0.38 200 OK (with content of edit page)
5. Time: 7.668847 192.168.0.38 to 192.168.0.35 POST /twiki/bin/rest/WysiwygPlugin/tml2html with no auth details
6. Time: 127.679797 192.168.0.35 to 192.168.0.38 401 Authorization Required
7. ...etc.

The two key questions seem to be to be:

1. Why aren't the auth details sent with request 5?
2. Why does Apache take 120 secs before it 401's the request? Why does it wait for a timeout?

BTW I don't think looking in TWiki code is going to be any help at all. This interaction is between the browser and Apache, and TWiki plays no part in it. If TWiki (or my Javascript) was getting the request headers wrong, I would expect to see this sort of wireshark trace on every TWiki. But it seems to be unique to yours

Later: I just reconfigured one of my TWikis to use Apache login and wiresharked it. I also don't see the authorization sent with the tml2html POST. After a bit of head-scratching I added rest to the list of scripts that require authentication in Apache, and it suddenly started sending the authorization header with the POST. My .htaccess now looks like this:

Options +ExecCGI
SetHandler cgi-script

ErrorDocument 401 /twiki/trunk/core/bin/view/TWiki/TWikiRegistration

<FilesMatch "(view|attach|edit|manage|rename|save|upload|mail|logon|rest|.*auth).*">
   AuthType Basic
   AuthName "TWiki4"
   AuthUserFile /home/twiki/htpasswd
   require valid-user
</FilesMatch>

However this still doesn't explain why you have this long pause from Apache before the 401, and I don't.

Try adding rest to the list of scripts requiring authentication (it's a major security hole not to have it there anyway)

-- TWiki:Main.CrawfordCurrie - 02 May 2008

I have taken a look at the httpd.conf files per your recent comment, and can share some observations;

I already had rest added to the FilesMatch directive, but I did not have view! adding view to the directive fixes this bug, but then prevents anonymous reading of the Twiki.

As to the lack of other GETs, I went back to the saved trace, and can confirm that there were no other requests, thus my browser must be caching the images/css/etc.

I have been trying to "catch" one of the httpd processes in the act, to run an strace on it, and have had limited success. If something comes of that, I will post it here. (and issues.apache.org, if relevant.)

Could you take the "view|" out of your FilesMatch directive, and run my testcase again? I suspect that you will (finally) encounter this delay. Either way, it would be helpful.

-- TWiki:Main.GavinMcDonald - 08 May 2008

I took view out of the FilesMatch and it made absolutely no difference.

I've been trying to educate myself on how the protocol is supposed to work. It's not completely clear to me under what circumstances FF is supposed to send authentication, but it would appear to be only in response to a 401. Certainly XmlHttpRequest doesn't send it unless it is explicitly told to do so.

-- CrawfordCurrie - 09 May 2008

Previously we have had somewhat similar issues with certain distributions - i.e. a standard redhat enterprise 4 / centos 4 has issues with long timeouts with twiki.

I don't think anyone ever got to the bottom of these problems, perhaps something similar is going on here (from the above it seems you're at a redhat installation, though I'm not sure which version).

Would it be a possibility for you to test this item at another distribution? For instance a default installation of Debian to see if the same symptoms occur there?

-- TWiki:Main.SteffenPoulsen - 09 May 2008

This is a redhat 4 distribution, so maybe it is the similar situation. Unfortunately, the only other distributions I have on site are Centos5...

-- TWiki:Main.GavinMcDonald - 15 May 2008

So, I played some more with the configs, and thought I'd share the data in hopes of further insight:

Up till now, TWiki has been configured to use sessions, Auth was TWiki::LoginManager::ApacheLogin. I had the FilesMatch directive as above in httpd.conf, nested within a directive.

If I switched Auth to TWiki::LoginManager::TemplateLogin, with no other changes, Users had to authenticate twice - Once via the template, and once via Apache. And they still caught the long-save bug. If I further comment out the section from httpd.conf, they are only prompted for their passwords via the template page, and the long-save bug disappears. This is a tenable solution for them, as TWiki is internal only, but it does not fix the "big picture."

It is probable that the root of this problem lies in the apache config, as opposed to TWiki proper, but imho, the config merely highlights a problem that would otherwise have gone unnoticed. Maybe, given that this may only manifest on a Redhat system, there is an interplay with apache that should not be.

To me the unanswered question is why credentials are not being passed through to /edit when required, or conversely, why the 401 takes so long to return.

Some limited ptrace'ing indicates that this could be a content-length header miscalculation - apache is reading the socket for X bytes, when it stalls, maybe only X-N are truly sent?

Alas, having found a solution, I can no longer bill the time I spend trouble shooting this, but if you have specific questions, I will try to oblige, lest this bug report languish.

-- TWiki:Main.GavinMcDonald - 15 May 2008

why credentials are not being passed through to /edit when required - I have done a lot of background reading on this now. As you know, HTTP is a stateless protocol. That means a client doesn't provide credentials with a request unless it is explicitly asked to do so by a preceding 401.

Your idea about content length is something that had occurred to me, so I checked it, and confirmed that the content-length header was correct. Possibly the calculation is wrong in your case, however; can you check?

having found a solution, I can no longer bill the time - well, I'm glad someone is getting paid for solving this!

-- CrawfordCurrie - 16 May 2008

I have hit this problem (5548), on a new twiki 4.2 install. It only happens on one twiki page, which has grown larger, over last few weeks. This page also has quite a large table in it, which I wonder if it is related to the problem.

The problem happens why I try and save an edit to this page. It spins and spins. I notice the 'save' process is running away with one of the system's CPUs (Solaris) and is in 100% USR CPU (application code).

This problem does not happen when saving from 'raw edit', just WYSIWYG edit.

When reviewing the call stacks (dtrace) of the save process, I see the following stacks, with counts...

libc_psr.so.1`memcpy+0x10 libperl.so.1`Perl_pp_uc+0x2a8 libperl.so.1`Perl_runops_standard+0x3c libperl.so.1`S_run_body+0x22c libperl.so.1`perl_run+0x338 perl`main+0x94 perl`_start+0x108

libc_psr.so.1`memcpy+0x1c libperl.so.1`Perl_pp_uc+0x2a8 libperl.so.1`Perl_runops_standard+0x3c libperl.so.1`S_run_body+0x22c libperl.so.1`perl_run+0x338 perl`main+0x94 perl`_start+0x108

libperl.so.1`Perl_runops_standard+0x3c libperl.so.1`S_run_body+0x22c libperl.so.1`perl_run+0x338 perl`main+0x94 perl`_start+0x108

libperl.so.1`Perl_runops_standard+0x38 libperl.so.1`S_run_body+0x22c libperl.so.1`perl_run+0x338 perl`main+0x94 perl`_start+0x108 167

In reviewing the stacks of the save process

-- TWiki:Main.JimNissen - 24 Jul 2008

Do you have an example long topic for us?

-- TWiki:Main.KennethLavrsen - 24 Jul 2008

No further feedback or follow up reports, so closing no-action.

-- CrawfordCurrie - 30 May 2009