Login works but it is slow. The log shows that one authentication try causes over 20 successful verifications -> over 20 mysql requests (my saslauthd has pam authmech and pam_mysql.so).
First verification:
Oct 29 13:32:39 h1630608 saslauthd: pam_mysql - option verbose is set to "true"
Oct 29 13:32:39 h1630608 saslauthd: pam_mysql - pam_sm_authenticate() called.
Oct 29 13:32:39 h1630608 saslauthd: pam_mysql - pam_mysql_converse() called.
Oct 29 13:32:39 h1630608 saslauthd: pam_mysql - pam_mysql_open_db() called.
Oct 29 13:32:39 h1630608 saslauthd: pam_mysql - pam_mysql_open_db() returning 0.
Oct 29 13:32:39 h1630608 saslauthd: pam_mysql - pam_mysql_check_passwd() called.
Oct 29 13:32:39 h1630608 saslauthd: pam_mysql - pam_mysql_format_string() called
Oct 29 13:32:39 h1630608 saslauthd: pam_mysql - pam_mysql_quick_escape() called.
Oct 29 13:32:39 h1630608 saslauthd: pam_mysql - SELECT *snapped query*
Oct 29 13:32:39 h1630608 saslauthd: pam_mysql - pam_mysql_check_passwd() returning 0.
Oct 29 13:32:39 h1630608 saslauthd: pam_mysql - pam_mysql_sql_log() called.
Oct 29 13:32:39 h1630608 saslauthd: pam_mysql - sqllog set but logtable not set
Oct 29 13:32:39 h1630608 saslauthd: pam_mysql - pam_sm_authenticate() returning 0.
Oct 29 13:32:39 h1630608 saslauthd: pam_mysql - pam_mysql_release_ctx() called.
Oct 29 13:32:39 h1630608 saslauthd: pam_mysql - pam_mysql_destroy_ctx() called.
Oct 29 13:32:39 h1630608 saslauthd: pam_mysql - pam_mysql_close_db() called.
Oct 29 13:32:41 h1630608 saslauthd: pam_mysql - option verbose is set to "true"
Oct 29 13:32:41 h1630608 saslauthd: pam_mysql - pam_sm_authenticate() called.
Oct 29 13:32:41 h1630608 saslauthd: pam_mysql - pam_mysql_converse() called.
Oct 29 13:32:41 h1630608 saslauthd: pam_mysql - pam_mysql_open_db() called.
Oct 29 13:32:41 h1630608 saslauthd: pam_mysql - pam_mysql_open_db() returning 0.
Oct 29 13:32:41 h1630608 saslauthd: pam_mysql - pam_mysql_check_passwd() called.
Oct 29 13:32:41 h1630608 saslauthd: pam_mysql - pam_mysql_format_string() called
Oct 29 13:32:41 h1630608 saslauthd: pam_mysql - pam_mysql_quick_escape() called.
Oct 29 13:32:41 h1630608 saslauthd: pam_mysql - SELECT *snapped query*
Oct 29 13:32:41 h1630608 saslauthd: pam_mysql - pam_mysql_check_passwd() returning 0.
Oct 29 13:32:41 h1630608 saslauthd: pam_mysql - pam_mysql_sql_log() called.
Oct 29 13:32:41 h1630608 saslauthd: pam_mysql - sqllog set but logtable not set
Oct 29 13:32:41 h1630608 saslauthd: pam_mysql - pam_sm_authenticate() returning 0.
Oct 29 13:32:41 h1630608 saslauthd: pam_mysql - pam_mysql_release_ctx() called.
Oct 29 13:32:41 h1630608 saslauthd: pam_mysql - pam_mysql_destroy_ctx() called.
Oct 29 13:32:41 h1630608 saslauthd: pam_mysql - pam_mysql_close_db() called.
You see the time difference. Nearly every page request needs now ~2 seconds. But the log is 100% identically.
If I use testsaslauthd there is only one verification… So I conclude that the problem is caused by anything related with mod\_authn\_sasl.
I had 13 httpd-prefork processes running at the time.
Sometimes it causes even 150 verifications that are all successful(pam\_mysql\_check\_passwd() returning 0.) but my browser gets no response. Its not sending several HTTP requests. When I sniff my network connection there is only one http request going out and one answer.
apache2/error_log has many Segmentation faults:
child pid 11764 exit signal Segmentation fault (11)
child pid 14390 exit signal Segmentation fault (11)
child pid 14391 exit signal Segmentation fault (11)
child pid 14402 exit signal Segmentation fault (11)
child pid 14400 exit signal Segmentation fault (11)
child pid 14403 exit signal Segmentation fault (11)
child pid 14401 exit signal Segmentation fault (11)
child pid 14582 exit signal Segmentation fault (11)
child pid 14572 exit signal Segmentation fault (11)
child pid 14584 exit signal Segmentation fault (11)
child pid 14583 exit signal Segmentation fault (11)
child pid 11590 exit signal Segmentation fault (11)
child pid 11782 exit signal Segmentation fault (11)
child pid 14579 exit signal Segmentation fault (11)
child pid 14581 exit signal Segmentation fault (11)
child pid 15446 exit signal Segmentation fault (11)
child pid 15447 exit signal Segmentation fault (11)
child pid 15448 exit signal Segmentation fault (11)
One login was between and . Between this time there were 150 verifications for one login:<br/>
First Verification: Oct 30 11:53:36<br/>
Last Verification: Oct 30 11:53:52
My Apache Version:
Server version: Apache/2.2.8 (Linux/SUSE)
Server built: Nov 23 2008 23:31:28
It's openSUSE 11.0
So please can anyone help me?
Btw the RegluarExpression in configure did not work on my apache version string so that i had to manipulate it:
ap_httpd_version="`$ap_httpd -v | grep 'version' | sed -e 's!.*/\(*\).*$!\1!'`"
instead
ap_httpd_version="`$ap_httpd -v | grep 'version' | sed -e 's!.*/\([.]*\).*$!\1!'`"
In my opinion both should work but for some reason seems not to work on my machine.
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
Thanks for the detailed report. I suppose you were using the latest version of the module?!
Regarding the 20 auth tries I'm pretty sure that it's apache itself that triggers them, if not your browser. The module itself does not contain any loops that could multiply requests from the core httpd. Does the page you request contain any images, external js or css that could trigger additional requests. Do you have any URL rewriting rules that could trigger subrequests in apache? To prove that assumption you could add some logging in the check\_password() function in mod\_authn\_sasl.c and compare the apache log with the one from pam\_mysql.
About the core dumps a backtrace would be helpful to see if it's caused by the sasl code and where. Let me know if you need help getting the backtrace.
Could you also run some tests in the shell regarding the problem with sed you ran into? I'm not aware that character classes should be a problem anywhere. The output of `echo 123 | sed -e 's!\([.]*\)!\1!'` would clearify if your sed behaves differently compared to mine. Could you please also post the output of `httpd -v` and `sed -version`
Thanks.
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
As far as I know I do not have URL rewrite rules active
(I have Plesk 9 running)
I concur with you. I have checked the mod\_auth_sasl.c before and saw no loop.
I protect a directory listing with the .htaccess file. It is impossible that there is more than one request from the browser since i sniffed my network traffic and saw only one http request.
The HTTP OK message comes after the last verification so that the browser cannot request any images earlier owing to the fact that there is no html sent before.
I will post another reply when I inserted some more logging.
I really don't think that this segmentation fault is caused by sasl code. I have faults also when there is nobody trying to authenticate.
your first command returns '123'.
GNU sed version 4.1.5
Server version: Apache/2.2.8 (Linux/SUSE)
Server built: Nov 23 2008 23:31:28
I see now too that is not the problem. I will investigate that problem further as soon as I have time.
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
The actual problem with the regex is not the space, but that the "/" matches the second slash instead of the first one. There's no digits and dots after that slash, so the expression does not match. I didn't expect another slash in the version string when I came up with the regex, my bad. This is how I intend to fix it: `/usr/sbin/httpd2 -v | grep 'version' | sed -e 's!*/\([.]*\).*$!\1!'`
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
I have setup a saslauthd and a folder with .htaccess:
AuthType Basic
AuthName "gft.eu"
AuthBasicProvider sasl
AuthBasicAuthoritative On
AuthSaslPwcheckMethod saslauthd
AuthSaslServiceName apache
AuthSaslRealm gft.eu
Require valid-user
Login works but it is slow. The log shows that one authentication try causes over 20 successful verifications -> over 20 mysql requests (my saslauthd has pam authmech and pam_mysql.so).
First verification:
Oct 29 13:32:39 h1630608 saslauthd: pam_mysql - option verbose is set to "true"
Oct 29 13:32:39 h1630608 saslauthd: pam_mysql - pam_sm_authenticate() called.
Oct 29 13:32:39 h1630608 saslauthd: pam_mysql - pam_mysql_converse() called.
Oct 29 13:32:39 h1630608 saslauthd: pam_mysql - pam_mysql_open_db() called.
Oct 29 13:32:39 h1630608 saslauthd: pam_mysql - pam_mysql_open_db() returning 0.
Oct 29 13:32:39 h1630608 saslauthd: pam_mysql - pam_mysql_check_passwd() called.
Oct 29 13:32:39 h1630608 saslauthd: pam_mysql - pam_mysql_format_string() called
Oct 29 13:32:39 h1630608 saslauthd: pam_mysql - pam_mysql_quick_escape() called.
Oct 29 13:32:39 h1630608 saslauthd: pam_mysql - SELECT *snapped query*
Oct 29 13:32:39 h1630608 saslauthd: pam_mysql - pam_mysql_check_passwd() returning 0.
Oct 29 13:32:39 h1630608 saslauthd: pam_mysql - pam_mysql_sql_log() called.
Oct 29 13:32:39 h1630608 saslauthd: pam_mysql - sqllog set but logtable not set
Oct 29 13:32:39 h1630608 saslauthd: pam_mysql - pam_sm_authenticate() returning 0.
Oct 29 13:32:39 h1630608 saslauthd: pam_mysql - pam_mysql_release_ctx() called.
Oct 29 13:32:39 h1630608 saslauthd: pam_mysql - pam_mysql_destroy_ctx() called.
Oct 29 13:32:39 h1630608 saslauthd: pam_mysql - pam_mysql_close_db() called.
. <br/>
.<br/>
.<br/>
(repeated 22 times)
Last verification that leads to HTTP OK message:
Oct 29 13:32:41 h1630608 saslauthd: pam_mysql - option verbose is set to "true"
Oct 29 13:32:41 h1630608 saslauthd: pam_mysql - pam_sm_authenticate() called.
Oct 29 13:32:41 h1630608 saslauthd: pam_mysql - pam_mysql_converse() called.
Oct 29 13:32:41 h1630608 saslauthd: pam_mysql - pam_mysql_open_db() called.
Oct 29 13:32:41 h1630608 saslauthd: pam_mysql - pam_mysql_open_db() returning 0.
Oct 29 13:32:41 h1630608 saslauthd: pam_mysql - pam_mysql_check_passwd() called.
Oct 29 13:32:41 h1630608 saslauthd: pam_mysql - pam_mysql_format_string() called
Oct 29 13:32:41 h1630608 saslauthd: pam_mysql - pam_mysql_quick_escape() called.
Oct 29 13:32:41 h1630608 saslauthd: pam_mysql - SELECT *snapped query*
Oct 29 13:32:41 h1630608 saslauthd: pam_mysql - pam_mysql_check_passwd() returning 0.
Oct 29 13:32:41 h1630608 saslauthd: pam_mysql - pam_mysql_sql_log() called.
Oct 29 13:32:41 h1630608 saslauthd: pam_mysql - sqllog set but logtable not set
Oct 29 13:32:41 h1630608 saslauthd: pam_mysql - pam_sm_authenticate() returning 0.
Oct 29 13:32:41 h1630608 saslauthd: pam_mysql - pam_mysql_release_ctx() called.
Oct 29 13:32:41 h1630608 saslauthd: pam_mysql - pam_mysql_destroy_ctx() called.
Oct 29 13:32:41 h1630608 saslauthd: pam_mysql - pam_mysql_close_db() called.
You see the time difference. Nearly every page request needs now ~2 seconds. But the log is 100% identically.
If I use testsaslauthd there is only one verification… So I conclude that the problem is caused by anything related with mod\_authn\_sasl.
I had 13 httpd-prefork processes running at the time.
Sometimes it causes even 150 verifications that are all successful(pam\_mysql\_check\_passwd() returning 0.) but my browser gets no response. Its not sending several HTTP requests. When I sniff my network connection there is only one http request going out and one answer.
apache2/error_log has many Segmentation faults:
child pid 11764 exit signal Segmentation fault (11)
child pid 14390 exit signal Segmentation fault (11)
child pid 14391 exit signal Segmentation fault (11)
child pid 14402 exit signal Segmentation fault (11)
child pid 14400 exit signal Segmentation fault (11)
child pid 14403 exit signal Segmentation fault (11)
child pid 14401 exit signal Segmentation fault (11)
child pid 14582 exit signal Segmentation fault (11)
child pid 14572 exit signal Segmentation fault (11)
child pid 14584 exit signal Segmentation fault (11)
child pid 14583 exit signal Segmentation fault (11)
child pid 11590 exit signal Segmentation fault (11)
child pid 11782 exit signal Segmentation fault (11)
child pid 14579 exit signal Segmentation fault (11)
child pid 14581 exit signal Segmentation fault (11)
child pid 15446 exit signal Segmentation fault (11)
child pid 15447 exit signal Segmentation fault (11)
child pid 15448 exit signal Segmentation fault (11)
One login was between and . Between this time there were 150 verifications for one login:<br/>
First Verification: Oct 30 11:53:36<br/>
Last Verification: Oct 30 11:53:52
My Apache Version:
Server version: Apache/2.2.8 (Linux/SUSE)
Server built: Nov 23 2008 23:31:28
It's openSUSE 11.0
So please can anyone help me?
Btw the RegluarExpression in configure did not work on my apache version string so that i had to manipulate it:
ap_httpd_version="`$ap_httpd -v | grep 'version' | sed -e 's!.*/\(*\).*$!\1!'`"
instead
ap_httpd_version="`$ap_httpd -v | grep 'version' | sed -e 's!.*/\([.]*\).*$!\1!'`"
In my opinion both should work but for some reason seems not to work on my machine.
Thanks for the detailed report. I suppose you were using the latest version of the module?!
Regarding the 20 auth tries I'm pretty sure that it's apache itself that triggers them, if not your browser. The module itself does not contain any loops that could multiply requests from the core httpd. Does the page you request contain any images, external js or css that could trigger additional requests. Do you have any URL rewriting rules that could trigger subrequests in apache? To prove that assumption you could add some logging in the check\_password() function in mod\_authn\_sasl.c and compare the apache log with the one from pam\_mysql.
About the core dumps a backtrace would be helpful to see if it's caused by the sasl code and where. Let me know if you need help getting the backtrace.
Could you also run some tests in the shell regarding the problem with sed you ran into? I'm not aware that character classes should be a problem anywhere. The output of `echo 123 | sed -e 's!\([.]*\)!\1!'` would clearify if your sed behaves differently compared to mine. Could you please also post the output of `httpd -v` and `sed -version`
Thanks.
Thanks for you answer!
As far as I know I do not have URL rewrite rules active
(I have Plesk 9 running)
I concur with you. I have checked the mod\_auth_sasl.c before and saw no loop.
I protect a directory listing with the .htaccess file. It is impossible that there is more than one request from the browser since i sniffed my network traffic and saw only one http request.
The HTTP OK message comes after the last verification so that the browser cannot request any images earlier owing to the fact that there is no html sent before.
I will post another reply when I inserted some more logging.
I really don't think that this segmentation fault is caused by sasl code. I have faults also when there is nobody trying to authenticate.
your first command returns '123'.
GNU sed version 4.1.5
Server version: Apache/2.2.8 (Linux/SUSE)
Server built: Nov 23 2008 23:31:28
I see now too that is not the problem. I will investigate that problem further as soon as I have time.
That's odd:
h1630608:/ # /usr/sbin/httpd2 -v | grep 'version' | sed -e 's!.*/\([.]*\).*$!\1!'
h1630608:/ # /usr/sbin/httpd2 -v | grep 'version' | sed -e 's!.*/\([.]*\)\s.*$!\1!'
2.2.8
For some reason .* does not match the space.
It is definitely a space char:
h1630608:/ # /usr/sbin/httpd2 -v > /tmp/test.txt
h1630608:/ # hexdump /tmp/test.txt
0000000 6553 7672 7265 7620 7265 6973 6e6f 203a
0000010 7041 6361 6568 322f 322e 382e 2820 694c
0000020 756e 2f78 5553 4553 0a29 6553 7672 7265
0000030 6220 6975 746c 203a 2020 6f4e 2076 3332
0000040 3220 3030 2038 3332 333a 3a31 3832 000a
000004f
(remember the big endian display of default hexdump)
The actual problem with the regex is not the space, but that the "/" matches the second slash instead of the first one. There's no digits and dots after that slash, so the expression does not match. I didn't expect another slash in the version string when I came up with the regex, my bad. This is how I intend to fix it: `/usr/sbin/httpd2 -v | grep 'version' | sed -e 's!*/\([.]*\).*$!\1!'`
I am also getting the "Segfault" problem, I have started a new forum entry for this.
Dave Hill