SSL Re-negotiation handshake failed - slow page loads
I have a redhat 6 server running coldfusion on apache. I require SSL to access the site and smart card authentication. That works fine, it logs in based on the smart card, and denies access without one. My problem is that the site takes about a minute per page to load, but it does load eventually. Looking at the logs when on level 'warn' it just tells me that the re-negotiation handshake failed: not accepted by client. More detailed on 'info' i get the following:
[Thu Sep 01 10:50:29 2011] [info] Configuring server for SSL protocol
1891 [Thu Sep 01 10:50:44 2011] [info] [client x.x.x.x] Connection to child 0 established (server my-server.com:443)
1892 [Thu Sep 01 10:50:44 2011] [info] Seeding PRNG with 144 bytes of entropy
1893 [Thu Sep 01 10:50:45 2011] [info] [client x.x.x.x] (70014)End of file found: SSL handshake interrupted by system [Hint: Stop button pressed in browser?!]
1894 [Thu Sep 01 10:50:45 2011] [info] [client x.x.x.x] Connection closed to child 0 with abortive shutdown (server my-server.com:443)
1895 [Thu Sep 01 10:50:45 2011] [info] [client x.x.x.x] Connection to child 0 established (server my-server.com:443)
1896 [Thu Sep 01 10:50:45 2011] [info] Seeding PRNG with 144 bytes of entropy
1897 [Thu Sep 01 10:50:45 2011] [info] [client x.x.x.x] (70014)End of file found: SSL handshake interrupted by system [Hint: Stop button pressed in browser?!]
1898 [Thu Sep 01 10:50:45 2011] [info] [client x.x.x.x] Connection closed to child 0 with abortive shutdown (server my-server.com:443)
1899 [Thu Sep 01 10:50:45 2011] [info] [client x.x.x.x] Connection to child 0 established (server my-server.com:443)
1900 [Thu Sep 01 10:50:45 2011] [info] Seeding PRNG with 144 bytes of entropy
1901 [Thu Sep 01 10:50:45 2011] [info] [client x.x.x.x] (70014)End of file found: SSL handshake interrupted by system [Hint: Stop button pressed in browser?!]
1902 [Thu Sep 01 10:50:45 2011] [info] [client x.x.x.x] Connection closed to child 0 with abortive shutdown (server my-server.com:443)
1903 [Thu Sep 01 10:50:45 2011] [info] [client x.x.x.x] Connection to child 0 established (server my-server.com:443)
1904 [Thu Sep 01 10:50:45 2011] [info] Seeding PRNG with 144 bytes of entropy
1905 [Thu Sep 01 10:50:45 2011] [info] [client x.x.x.x] (70014)End of file found: SSL handshake interrupted by system [Hint: Stop button pressed in browser?!]
1906 [Thu Sep 01 10:50:45 2011] [info] [client x.x.x.x] Connection closed to child 0 with abortive shutdown (server my-server.com:443)
1907 [Thu Sep 01 10:50:45 2011] [info] [client x.x.x.x] Connection to child 0 established (server my-server.com:443)
1908 [Thu Sep 01 10:50:45 2011] [info] Seeding PRNG with 144 bytes of entropy
1909 [Thu Sep 01 10:50:45 2011] [info] [client x.x.x.x] (70014)End of file found: SSL handshake interrupted by system [Hint: Stop button pressed in browser?!]
1910 [Thu Sep 01 10:50:45 2011] [info] [client x.x.x.x] Connection closed to child 0 with abortive shutdown (server my-server.com:443)
1911 [Thu Sep 01 10:50:45 2011] [info] [client x.x.x.x] Connection to child 0 established (server my-server.com:443)
1912 [Thu Sep 01 10:50:45 2011] [info] Seeding PRNG with 144 bytes of entropy
1913 [Thu Sep 01 10:50:45 2011] [info] [client x.x.x.x] (70014)End of file found: SSL handshake interrupted by system [Hint: Stop button pressed in browser?!]
1914 [Thu Sep 01 10:50:45 2011] [info] [client x.x.x.x] Connection closed to child 0 with abortive shutdown (server my-server.com:443)
1915 [Thu Sep 01 10:50:45 2011] [info] [client x.x.x.x] Connection to child 0 established (server my-server.com:443)
1916 [Thu Sep 01 10:50:45 2011] [info] Seeding PRNG with 144 bytes of entropy
1917 [Thu Sep 01 10:50:45 2011] [info] Initial (No.1) HTTPS request received for child 0 (server my-server.com:443)
1918 [Thu Sep 01 10:50:45 2011] [info] [client x.x.x.x] Requesting connection re-negotiation
1919 [Thu Sep 01 10:50:45 2011] [info] [client x.x.x.x] Awaiting re-negotiation handshake
1920 [Thu Sep 01 10:50:45 2011] [info] [client x.x.x.x] Connection to child 1 established (server my-server.com:443)
1921 [Thu Sep 01 10:50:45 2011] [info] Seeding PRNG with 144 bytes of entropy
1922 [Thu Sep 01 10:50:45 2011] [error] [client x.x.x.x] Re-negotiation handshake failed: Not accepted by client!?
1923 [Thu Sep 01 10:50:45 2011] [info] [client x.x.x.x] Connection to child 0 established (server my-server.com:443)
1924 [Thu Sep 01 10:50:45 2011] [info] Seeding PRNG with 144 bytes of entropy
1925 [Thu Sep 01 10:50:45 2011] [info] Initial (No.1) HTTPS request received for child 1 (server my-server.com:443)
1926 [Thu Sep 01 10:50:45 2011] [info] [client x.x.x.x] Requesting connection re-negotiation
1927 [Thu Sep 01 10:50:45 2011] [info] [client x.x.x.x] Awaiting re-negotiation handshake
1928 [Thu Sep 01 10:50:45 2011] [error] [client x.x.x.x] Re-negotiation handshake failed: Not accepted by client!?
1929 [Thu Sep 01 10:50:45 2011] [info] [client x.x.x.x] Connection to child 1 established (server my-server.com:443)
1930 [Thu Sep 01 10:50:45 2011] [info] Seeding PRNG with 144 bytes of entropy
1931 [Thu Sep 01 10:50:45 2011] [info] Initial (No.1) HTTPS request received for child 0 (server my-server.com:443)
1932 [Thu Sep 01 10:50:45 2011] [info] [client x.x.x.x] Requesting connection re-negotiation
1933 [Thu Sep 01 10:50:45 2011] [info] [client x.x.x.x] Awaiting re-negotiation handshake
1934 [Thu Sep 01 10:50:45 2011] [error] [client x.x.x.x] Re-negotiation handshake failed: Not accepted by client!?
1935 [Thu Sep 01 10:50:45 2011] [info] Initial (No.1) HTTPS request received for child 1 (server my-server.com:443)
1936 [Thu Sep 01 10:50:45 2011] [info] [client x.x.x.x] Requesting connection re-negotiation
1937 [Thu Sep 01 10:50:45 2011] [info] [client x.x.x.x] Awaiting re-negotiation handshake
1938 [Thu Sep 01 10:50:47 2011] [info] [client x.x.x.x] Connection closed to child 1 with standard shutdown (server my-server.com:443)
1939 [Thu Sep 01 10:50:47 2011] [info] [client x.x.x.x] Connection to child 0 established (server my-server.com:443)
1940 [Thu Sep 01 10:50:47 2011] [info] [client x.x.x.x] Connection to child 2 established (server my-server.com:443)
1941 [Thu Sep 01 10:50:47 2011] [info] Seeding PRNG with 144 bytes of entropy
1942 [Thu Sep 01 10:50:47 2011] [info] Seeding PRNG with 144 bytes of entropy
1943 [Thu Sep 01 10:50:47 2011] [info] [client x.x.x.x] Connection to child 3 established (server my-server.com:443)
1944 [Thu Sep 01 10:50:47 2011] [info] Seeding PRNG with 144 bytes of entropy
1945 [Thu Sep 01 10:50:47 2011] [info] [client x.x.x.x] Connection to child 4 established (server my-server.com:443)
1946 [Thu Sep 01 10:50:47 2011] [info] Seeding PRNG with 144 bytes of entropy
1947 [Thu Sep 01 10:50:47 2011] [info] [client x.x.x.x] Connection to child 6 established (server my-server.com:443)
1948 [Thu Sep 01 10:50:47 2011] [info] Seeding PRNG with 144 bytes of entropy
1949 [Thu Sep 01 10:50:47 2011] [info] [client x.x.x.x] Connection to child 5 established (server my-server.com:443)
1950 [Thu Sep 01 10:50:47 2011] [info] Seeding PRNG with 144 bytes of entropy
1951 [Thu Sep 01 10:50:47 2011] [info] [client x.x.x.x] (70014)End of file found: SSL handshake interrupted by system [Hint: Stop button pressed in browser?!]
1952 [Thu Sep 01 10:50:47 2011] [info] [client x.x.x.x] Connection closed to child 0 with abortive shutdown (server my-server.com:443)
1953 [Thu Sep 01 10:50:47 2011] [info] [client x.x.x.x] (70014)End of file found: SSL handshake interrupted by system [Hint: Stop button pressed in browser?!]
1954 [Thu Sep 01 10:50:47 2011] [info] [client x.x.x.x] Connection closed to child 2 with abortive shutdown (server my-server.com:443)
1955 [Thu Sep 01 10:50:47 2011] [info] [client x.x.x.x] (70014)End of file found: SSL handshake interrupted by system [Hint: Stop button pressed in browser?!]
1956 [Thu Sep 01 10:50:47 2011] [info] [client x.x.x.x] Connection closed to child 4 with abortive shutdown (server my-server.com:443)
1957 [Thu Sep 01 10:50:47 2011] [info] [client x.x.x.x] (70014)End of file found: SSL handshake interrupted by system [Hint: Stop button pressed in browser?!]
1958 [Thu Sep 01 10:50:47 2011] [info] [client x.x.x.x] Connection closed to child 6 with abortive shutdown (server my-server.com:443)
1959 [Thu Sep 01 10:50:47 2011] [info] [client x.x.x.x] (70014)End of file found: SSL handshake interrupted by system [Hint: Stop button pressed in browser?!]
I am having the same kind of problem.
When i put my
SSLVerifyClient require
SSLVerifyDepth 1
inside a <Directory> directive it is slow and i get Re-negotiation messages in the error log.
If i move these directives to top-level (under ) everything works like a charm.