Bug #6467 random authentican failure
Submitted: 5 Nov 2004 16:22 Modified: 11 Jan 2005 12:08
Reporter: James Kupernik Email Updates:
Status: Can't repeat Impact on me:
None 
Category:MySQL Server Severity:S3 (Non-critical)
Version:4.0.21 OS:Linux (RedHat)
Assigned to: CPU Architecture:Any

[5 Nov 2004 16:22] James Kupernik
Description:
On any installation verision of MySQL to my system (doesn't matter if its RPM, binary, or compiled) it creates this random authentication error. If I create users with passwords, 90% of the time, the authentication goes through fine, but another 10% of the time, MySQL will say the password is bad, when in fact it is correct. If I don't use passwords for the users then there is no issue.

This happens at all forms of connection (PHP, commandline, etc).

Here is the trace report:
T@147466: info: check_connections called by thread 1
T@147466: info: New connection received on socket (16)
T@147466: info: Host: localhost
T@147466: >vio_keepalive
T@147466: | enter: sd=16, set_keep_alive=1
T@147466: <vio_keepalive
T@147466: >net_write_command
T@147466: | enter: length: 48
T@147466: <net_write_command
T@147466: >net_flush
T@147466: | >vio_is_blocking
T@147466: | | exit: 0
T@147466: | <vio_is_blocking
T@147466: | >net_real_write
T@147466: | | >vio_write
T@147466: | | | enter: sd=16, buf=0x8976e50, size=53
T@147466: | | | exit: 53
T@147466: | | <vio_write
T@147466: | <net_real_write
T@147466: <net_flush
T@147466: >vio_is_blocking
T@147466: | exit: 0
T@147466: <vio_is_blocking
T@147466: >vio_read
T@147466: | enter: sd=16, buf=0x8976e50, size=4
T@147466: | vio_error: Got error 11 during read
T@147466: | exit: -1
T@147466: <vio_read
T@147466: info: vio_read returned -1,  errno: 11
T@147466: >thr_alarm
T@147466: | enter: thread: T@147466  sec: 5
T@147466: | info: reschedule
T@147466: <thr_alarm
T@147466: >vio_blocking
T@147466: | enter: set_blocking_mode: 1  old_mode: 0
T@147466: | exit: 0
T@147466: <vio_blocking
T@147466: >vio_read
T@147466: | enter: sd=16, buf=0x8976e50, size=4
T@147466: | exit: 4
T@147466: <vio_read
T@147466: >vio_read
T@147466: | enter: sd=16, buf=0x8976e50, size=19
T@131081: | >process_alarm
T@131081: | | info: sig: 14  active alarms: 1
T@147466: | exit: 19
T@147466: <vio_read
T@147466: >thr_end_alarm
T@131081: | <process_alarm
T@147466: <thr_end_alarm
T@147466: >vio_blocking
T@147466: | enter: set_blocking_mode: 0  old_mode: 1
T@147466: | exit: 0
T@147466: <vio_blocking
T@147466: >my_malloc
T@147466: | my: Size: 8200  MyFlags: 16
T@147466: | exit: ptr: 8978e60
T@147466: <my_malloc
T@147466: >my_malloc
T@147466: | my: Size: 6  MyFlags: 0
T@147466: | exit: ptr: 8972d88
T@147466: <my_malloc
T@147466: >acl_getroot
T@147466: | >wild_case_compare
T@147466: | | enter: str: 'localhost'  wildstr: 'zeus'
T@147466: | <wild_case_compare
T@147466: | >wild_case_compare
T@147466: | | enter: str: 'localhost'  wildstr: 'localhost'
T@147466: | <wild_case_compare
T@147466: <acl_getroot
T@147466: info: Capabilities: 9221  packet_length: 0  Host: 'localhost'  Login user: 'jkupe'  Priv_user: 'jkupe'  Using password: yes  Access: 1073741824  db: '*none*'
T@147466: >net_printf
T@147466: | enter: message: 1045
T@147466: | >query_cache_abort
T@147466: | <query_cache_abort
T@147466: | >vio_is_blocking
T@147466: | | exit: 0
T@147466: | <vio_is_blocking
T@147466: | >net_real_write
T@147466: | | >vio_write
T@147466: | | | enter: sd=16, buf=0x8976e50, size=70
T@147466: | | | exit: 70
T@147466: | | <vio_write
T@147466: | <net_real_write
T@147466: <net_printf
T@147466: >close_connection
T@147466: | enter: fd: socket (16)  error: ''
T@147466: | >vio_close
T@147466: | <vio_close
T@147466: <close_connection
T@147466: >end_thread
T@147466: | >THD::cleanup
T@147466: | | >ha_rollback
T@147466: | | | >reinit_io_cache
T@147466: | | | | enter: cache: 898198c type: 1  seek_offset: 0  clear_cache: 1
T@147466: | | | <reinit_io_cache
T@147466: | | <ha_rollback
T@147466: | | >hash_free
T@147466: | | | >my_free
T@147466: | | | | my: ptr: 8987688
T@147466: | | | <my_free
T@147466: | | <hash_free
T@147466: | <THD::cleanup
T@147466: | >~THD()
T@147466: | | >my_free
T@147466: | | | my: ptr: 8981c50
T@147466: | | <my_free
T@147466: | | >net_end
T@147466: | | | >my_free
T@147466: | | | | my: ptr: 8976e50
T@147466: | | | <my_free
T@147466: | | <net_end
T@147466: | | >close_cached_file
T@147466: | | | >end_io_cache
T@147466: | | | | >my_free
T@147466: | | | | | my: ptr: 899ba10
T@147466: | | | | <my_free
T@147466: | | | <end_io_cache
T@147466: | | | >my_free
T@147466: | | | | my: ptr: 8987710
T@147466: | | | <my_free
T@147466: | | | >my_free
T@147466: | | | | my: ptr: 8972d78
T@147466: | | | <my_free
T@147466: | | <close_cached_file
T@147466: | | info: freeing host
T@147466: | | >my_free
T@147466: | | | my: ptr: 8972d88
T@147466: | | <my_free
T@147466: | | >free_root
T@147466: | | <free_root
T@147466: | | >free_root
T@147466: | | <free_root
T@147466: | <~THD()
T@147466: | >my_free
T@147466: | | my: ptr: 8978e60
T@147466: | <my_free
T@147466: | >my_free
T@147466: | | my: ptr: 8981310
T@147466: | <my_free
T@147466: | info: sending a broadcast
T@147466: | info: unlocked thread_count mutex
T@16384: | >my_malloc
T@16384: | | my: Size: 2364  MyFlags: 24
T@16384: | | exit: ptr: 8981310
T@16384: | <my_malloc
T@16384: | >hash_init
T@16384: | | enter: hash: 8981780  size: 16
T@16384: | | >init_dynamic_array
T@16384: | | | >my_malloc
T@16384: | | | | my: Size: 128  MyFlags: 16
T@16384: | | | | exit: ptr: 8987688
T@16384: | | | <my_malloc
T@16384: | | <init_dynamic_array
T@16384: | <hash_init
T@16384: | >open_cached_file
T@16384: | | >my_malloc
T@16384: | | | my: Size: 6  MyFlags: 16
T@16384: | | | exit: ptr: 8987710
T@16384: | | <my_malloc
T@16384: | | >my_malloc
T@16384: | | | my: Size: 3  MyFlags: 16
T@16384: | | | exit: ptr: 8972d78
T@16384: | | <my_malloc
T@16384: | | >init_io_cache
T@16384: | | | enter: cache: 898198c  type: 1  pos: 0
T@16384: | | | >my_malloc
T@16384: | | | | my: Size: 32768  MyFlags: 4
T@16384: | | | | exit: ptr: 899ba10
T@16384: | | | <my_malloc
T@16384: | | | info: init_io_cache: cachesize = 32768
T@16384: | | <init_io_cache
T@16384: | <open_cached_file
T@16384: | >vio_new
T@16384: | | enter: sd=16
T@16384: | | >my_malloc
T@16384: | | | my: Size: 84  MyFlags: 16
T@16384: | | | exit: ptr: 8981c50
T@16384: | | <my_malloc
T@16384: | | >vio_reset
T@16384: | | | enter: type=2  sd=16  localhost=1
T@16384: | | <vio_reset
T@16384: | <vio_new
T@16384: | >my_net_init
T@16384: | | >my_malloc
T@16384: | | | my: Size: 8199  MyFlags: 16
T@16384: | | | exit: ptr: 8976e50
T@16384: | | <my_malloc
T@16384: | | >vio_blocking
T@16384: | | | enter: set_blocking_mode: 0  old_mode: 1
T@16384: | | | exit: 0
T@16384: | | <vio_blocking
T@16384: | | >vio_fastsend
T@16384: | | | exit: 0
T@16384: | | <vio_fastsend
T@16384: | <my_net_init
T@16384: | >create_new_thread
T@16384: | | info: creating thread 2
T@16384: | | info: Thread created
T@16384: | <create_new_thread
T@163850: info: handle_one_connection called by thread 2

T@163850: info: check_connections called by thread 2
T@163850: info: New connection received on socket (16)
T@163850: info: Host: localhost
T@163850: >vio_keepalive
T@163850: | enter: sd=16, set_keep_alive=1
T@163850: <vio_keepalive
T@163850: >net_write_command
T@163850: | enter: length: 48
T@163850: <net_write_command
T@163850: >net_flush
T@163850: | >vio_is_blocking
T@163850: | | exit: 0
T@163850: | <vio_is_blocking
T@163850: | >net_real_write
T@163850: | | >vio_write
T@163850: | | | enter: sd=16, buf=0x8976e50, size=53
T@163850: | | | exit: 53
T@163850: | | <vio_write
T@163850: | <net_real_write
T@163850: <net_flush
T@163850: >vio_is_blocking
T@163850: | exit: 0
T@163850: <vio_is_blocking
T@163850: >vio_read
T@163850: | enter: sd=16, buf=0x8976e50, size=4
T@163850: | vio_error: Got error 11 during read
T@163850: | exit: -1
T@163850: <vio_read
T@163850: info: vio_read returned -1,  errno: 11
T@163850: >thr_alarm
T@163850: | enter: thread: T@163850  sec: 5
T@163850: | info: reschedule
T@163850: <thr_alarm
T@131081: | >process_alarm
T@131081: | | info: sig: 14  active alarms: 1
T@131081: | <process_alarm
T@163850: >vio_blocking
T@163850: | enter: set_blocking_mode: 1  old_mode: 0
T@163850: | exit: 0
T@163850: <vio_blocking
T@163850: >vio_read
T@163850: | enter: sd=16, buf=0x8976e50, size=4
T@163850: | exit: 4
T@163850: <vio_read
T@163850: >vio_read
T@163850: | enter: sd=16, buf=0x8976e50, size=19
T@163850: | exit: 19
T@163850: <vio_read
T@163850: >thr_end_alarm
T@163850: <thr_end_alarm
T@163850: >vio_blocking
T@163850: | enter: set_blocking_mode: 0  old_mode: 1
T@163850: | exit: 0
T@163850: <vio_blocking
T@163850: >my_malloc
T@163850: | my: Size: 8200  MyFlags: 16
T@163850: | exit: ptr: 8978e60
T@163850: <my_malloc
T@163850: >my_malloc
T@163850: | my: Size: 6  MyFlags: 0
T@163850: | exit: ptr: 8972d88
T@163850: <my_malloc
T@163850: >acl_getroot
T@163850: | >wild_case_compare
T@163850: | | enter: str: 'localhost'  wildstr: 'zeus'
T@163850: | <wild_case_compare
T@163850: | >wild_case_compare
T@163850: | | enter: str: 'localhost'  wildstr: 'localhost'
T@163850: | <wild_case_compare
T@163850: <acl_getroot
T@163850: info: Capabilities: 9221  packet_length: 0  Host: 'localhost'  Login user: 'jkupe'  Priv_user: 'jkupe'  Using password: yes  Access: 0  db: '*none*'
T@163850: >send_ok
T@163850: | packet_header: Memory: be7ff7b4  Bytes: (4)
05 00 00 02 
T@163850: | >net_flush
T@163850: | | >vio_is_blocking
T@163850: | | | exit: 0
T@163850: | | <vio_is_blocking
T@163850: | | >net_real_write
T@163850: | | | >vio_write
T@163850: | | | | enter: sd=16, buf=0x8976e50, size=9
T@163850: | | | | exit: 9
T@163850: | | | <vio_write
T@163850: | | <net_real_write
T@163850: | <net_flush
T@163850: <send_ok
T@163850: >my_malloc
T@163850: | my: Size: 8208  MyFlags: 0
T@163850: | exit: ptr: 89a3a18
T@163850: <my_malloc
T@163850: >my_malloc
T@163850: | my: Size: 4112  MyFlags: 0
T@163850: | exit: ptr: 897d910
T@163850: <my_malloc
T@163850: >do_command
T@163850: | >vio_is_blocking
T@163850: | | exit: 0
T@163850: | <vio_is_blocking
T@163850: | >vio_read
T@163850: | | enter: sd=16, buf=0x8976e50, size=4
T@163850: | | vio_error: Got error 11 during read
T@163850: | | exit: -1
T@163850: | <vio_read
T@163850: | info: vio_read returned -1,  errno: 11
T@163850: | >thr_alarm
T@163850: | | enter: thread: T@163850  sec: 28800
T@163850: | | info: reschedule
T@163850: | <thr_alarm
T@163850: | >vio_blocking
T@163850: | | enter: set_blocking_mode: 1  old_mode: 0
T@163850: | | exit: 0
T@163850: | <vio_blocking
T@163850: | >vio_read
T@163850: | | enter: sd=16, buf=0x8976e50, size=4
T@131081: | >process_alarm
T@131081: | | info: sig: 14  active alarms: 1
T@131081: | <process_alarm
T@16384: | >my_malloc
T@16384: | | my: Size: 2364  MyFlags: 24
T@16384: | | exit: ptr: 897ae70
T@16384: | <my_malloc
T@16384: | >hash_init
T@16384: | | enter: hash: 897b2e0  size: 16
T@16384: | | >init_dynamic_array
T@16384: | | | >my_malloc
T@16384: | | | | my: Size: 128  MyFlags: 16
T@16384: | | | | exit: ptr: 8981e08
T@16384: | | | <my_malloc
T@16384: | | <init_dynamic_array
T@16384: | <hash_init
T@16384: | >open_cached_file
T@16384: | | >my_malloc
T@16384: | | | my: Size: 6  MyFlags: 16
T@16384: | | | exit: ptr: 8981e90
T@16384: | | <my_malloc
T@16384: | | >my_malloc
T@16384: | | | my: Size: 3  MyFlags: 16
T@16384: | | | exit: ptr: 8981ea0
T@16384: | | <my_malloc
T@16384: | | >init_io_cache
T@16384: | | | enter: cache: 897b4ec  type: 1  pos: 0
T@16384: | | | >my_malloc
T@16384: | | | | my: Size: 32768  MyFlags: 4
T@16384: | | | | exit: ptr: 89a5a30
T@16384: | | | <my_malloc
T@16384: | | | info: init_io_cache: cachesize = 32768
T@16384: | | <init_io_cache
T@16384: | <open_cached_file
T@16384: | >vio_new
T@16384: | | enter: sd=17
T@16384: | | >my_malloc
T@16384: | | | my: Size: 84  MyFlags: 16
T@16384: | | | exit: ptr: 8981eb0
T@16384: | | <my_malloc
T@16384: | | >vio_reset
T@16384: | | | enter: type=1  sd=17  localhost=0
T@16384: | | <vio_reset
T@16384: | <vio_new
T@16384: | >my_net_init
T@16384: | | >my_malloc
T@16384: | | | my: Size: 8199  MyFlags: 16
T@16384: | | | exit: ptr: 89ada38
T@16384: | | <my_malloc
T@16384: | | >vio_blocking
T@16384: | | | enter: set_blocking_mode: 0  old_mode: 1
T@16384: | | | exit: 0
T@16384: | | <vio_blocking
T@16384: | | >vio_fastsend
T@16384: | | | exit: 0
T@16384: | | <vio_fastsend
T@16384: | <my_net_init
T@16384: | >create_new_thread
T@16384: | | info: creating thread 3
T@16384: | | info: Thread created
T@16384: | <create_new_thread
T@180235: info: handle_one_connection called by thread 3

How to repeat:
I can make this happen by just continuing connection attempts, and 1 out 10 times it will fail.
[11 Jan 2005 12:06] Aleksey Kishkin
test

Attachment: bug6467.pl (application/x-perl, text), 158 bytes.

[11 Jan 2005 12:08] Aleksey Kishkin
wrote a test case (attached, in file section), but didn't get any error messages. We need more info.
[11 Jan 2005 14:08] James Kupernik
It only fails when you assign a password to a username. Using no password is successful 100% of the time ...

I'm going to run your script and paste the error message here.
[11 Jan 2005 14:51] James Kupernik
[root@zeus jkupe]# perl bug6467.pl
DBI connect('test','root',...) failed: Access denied for user: 'root@localhost' (Using password: YES) at bug6467.pl line 7
4 connection Access denied for user: 'root@localhost' (Using password: YES) at bug6467.pl line 7.
[root@zeus jkupe]# perl bug6467.pl
DBI connect('test','root',...) failed: Access denied for user: 'root@localhost' (Using password: YES) at bug6467.pl line 7
45 connection Access denied for user: 'root@localhost' (Using password: YES) at bug6467.pl line 7.
[root@zeus jkupe]# perl bug6467.pl
DBI connect('test','root',...) failed: Access denied for user: 'root@localhost' (Using password: YES) at bug6467.pl line 7
54 connection Access denied for user: 'root@localhost' (Using password: YES) at bug6467.pl line 7.
[root@zeus jkupe]# perl bug6467.pl
DBI connect('test','root',...) failed: Access denied for user: 'root@localhost' (Using password: YES) at bug6467.pl line 7
17 connection Access denied for user: 'root@localhost' (Using password: YES) at bug6467.pl line 7.
[root@zeus jkupe]# perl bug6467.pl
DBI connect('test','root',...) failed: Access denied for user: 'root@localhost' (Using password: YES) at bug6467.pl line 7
56 connection Access denied for user: 'root@localhost' (Using password: YES) at bug6467.pl line 7.
[11 Jan 2005 17:33] Aleksey Kishkin
i've add new user, set password for him and run testcase again with non-empty password field in DBI->connect.

Run 5 times, every time without any error.

If you have any other ideas what can be a cause of error you noticed, pls let me know.
[11 Jan 2005 17:36] James Kupernik
I wish I knew ... this is the only system which I have had an issue on.

When I talked to one of the MySQL developers at Linux World last winter, they told me to get an log output from mysql and submit it.