Bug 4372 - Long timeout in LDAP setup when accessing files after 10 secs
Summary: Long timeout in LDAP setup when accessing files after 10 secs
Status: RESOLVED FIXED
Alias: None
Product: Samba 3.0
Classification: Unclassified
Component: File Services (show other bugs)
Version: 3.0.22
Hardware: x86 Linux
: P3 major
Target Milestone: none
Assignee: Volker Lendecke
QA Contact: Samba QA Contact
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2007-02-06 10:15 UTC by Joachim Hergeth
Modified: 2007-02-09 15:28 UTC (History)
0 users

See Also:


Attachments
Proposed patch (4.03 KB, patch)
2007-02-09 15:01 UTC, Volker Lendecke
no flags Details
Revised patch (4.03 KB, patch)
2007-02-09 15:28 UTC, Volker Lendecke
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Joachim Hergeth 2007-02-06 10:15:31 UTC
We use Samba 3.0.22 on a Suse 10 system in connection with OpenLDAP with ca. 25 users. Both SAMBA and OpenLDAP are on the same server.

Performance is usually good when saving files stored on a samba share. But if a file is saved after more then 10 secs without any transmission to samba, a 10 second delay occurs.
Example: Hugo edits a file in Word and uses Ctrl+S to save the file. If there are more then 10 seconds (estimate) between two Ctrl+S, the time for the write operation increases from below a second to more then 10 seconds.

After checking with "File Monitor" from sysinternals I found:
722	16:34:16	WINWORD.EXE:1916	QUERY SECURITY	T:\Joachim\~WRD1690.tmp	SUCCESS		
723	16:34:16	WINWORD.EXE:1916	SET SECURITY	T:\Joachim\~WRD1690.tmp	SUCCESS		
724	16:34:27	WINWORD.EXE:1916	CLOSE	T:\Joachim\~WRD1690.tmp	SUCCESS		
725	16:34:27	WINWORD.EXE:1916	QUERY INFORMATION	T:\Joachim\Netzwerkstruktur.doc	SUCCESS	FileStreamInformation	

A 11 second delay during security changes on the temp file.
I increased the samba log file settings to 10 and checked there:
[2007/02/06 16:31:41, 5] lib/smbldap.c:smbldap_search_ext(1101)
  smbldap_search_ext: base => [dc=master-ldap,dc=gts-systems.de], filter => [(&(sambaSID=S-1-5-21-1623290758-3047616346-2689135926-513)(objectclass=sambaSamAccount))], scope => [2]
[2007/02/06 16:31:41, 11] lib/smbldap.c:smbldap_open(973)
  smbldap_open: already connected to the LDAP server
[2007/02/06 16:31:42, 11] lib/smbldap.c:smbldap_open(973)
  smbldap_open: already connected to the LDAP server
[2007/02/06 16:31:43, 11] lib/smbldap.c:smbldap_open(973)
  smbldap_open: already connected to the LDAP server
[2007/02/06 16:31:44, 11] lib/smbldap.c:smbldap_open(973)
  smbldap_open: already connected to the LDAP server
[2007/02/06 16:31:45, 11] lib/smbldap.c:smbldap_open(973)
  smbldap_open: already connected to the LDAP server
[2007/02/06 16:31:46, 11] lib/smbldap.c:smbldap_open(973)
  smbldap_open: already connected to the LDAP server
[2007/02/06 16:31:47, 11] lib/smbldap.c:smbldap_open(973)
  smbldap_open: already connected to the LDAP server
[2007/02/06 16:31:48, 11] lib/smbldap.c:smbldap_open(973)
  smbldap_open: already connected to the LDAP server
[2007/02/06 16:31:49, 11] lib/smbldap.c:smbldap_open(973)
  smbldap_open: already connected to the LDAP server
[2007/02/06 16:31:50, 11] lib/smbldap.c:smbldap_open(973)
  smbldap_open: already connected to the LDAP server
[2007/02/06 16:31:51, 11] lib/smbldap.c:smbldap_open(973)
  smbldap_open: already connected to the LDAP server
[2007/02/06 16:31:52, 10] lib/smbldap.c:smb_ldap_setup_conn(568)
  smb_ldap_setup_connection: ldap://localhost
[2007/02/06 16:31:52, 2] lib/smbldap.c:smbldap_open_connection(724)
  smbldap_open_connection: connection opened
[2007/02/06 16:31:52, 10] lib/smbldap.c:smbldap_connect_system(883)

The LDAP connection seems to be open, but SAMBA does not realize it.
Now I checked the SAMBA sources and found in file "smbldap.c" a function "smbldap_search_ext" which generates the first log entry. Later on this functions enters a while-loop which is left only if the function "another_ldap_try" returns false. This function is:
static int another_ldap_try(struct smbldap_state *ldap_state, int *rc,
			    int *attempts, time_t endtime)
{
	time_t now = time(NULL);
	int open_rc = LDAP_SERVER_DOWN;

	if (*rc != LDAP_SERVER_DOWN)
		goto no_next;

	if (now >= endtime) {
		smbldap_close(ldap_state);
		*rc = LDAP_TIMEOUT;
		goto no_next;
	}

	if (*attempts == 0) {
		got_alarm = False;
		old_handler = CatchSignal(SIGALRM, gotalarm_sig);
		alarm(endtime - now);

		if (ldap_state->pid != sys_getpid())
			smbldap_close(ldap_state);
	}

1>>>>	while (1) {

		if (*attempts != 0)
			smb_msleep(1000);

		*attempts += 1;

		open_rc = smbldap_open(ldap_state);

		if (open_rc == LDAP_SUCCESS) {
			ldap_state->last_use = now;
2>>>>			return True;
		}

		if (open_rc == LDAP_INSUFFICIENT_ACCESS) {
			/* The fact that we are non-root or any other
			 * access-denied condition will not change in the next
			 * round of trying */
			*rc = open_rc;
			break;
		}

		if (got_alarm) {
			*rc = LDAP_TIMEOUT;
			break;
		}

		if (open_rc != LDAP_SUCCESS) {
			DEBUG(1, ("Connection to LDAP server failed for the "
				  "%d try!\n", *attempts));
		}
	}

 no_next:
3>>>>	CatchSignal(SIGALRM, old_handler);
	alarm(0);
	ldap_state->last_use = now;
	return False;
}

Please observe that the forever loop at "1>>>>" is left when a LDAP connection exists 2>>>>! But !!!!! the ciorrect way to leave the loop would be to jump to label "no_next" at 3>>>>.
I think this is a bug. Beyond returning TRUE instead of FALSE also several other ressources are NOT released (signal handler, alarm).

I am not familiar with developing under Linux. So I can not change the source my self and check this. So please comment on my findings.

Thanks for your interest,

J. Hergeth
Comment 1 Volker Lendecke 2007-02-06 11:33:27 UTC
Seems right -- looking at it.

Volker
Comment 2 Joachim Hergeth 2007-02-06 11:57:31 UTC
Unfortunately it is even more difficult....
The function "smbldap_search_ext" which calls "another_ldap_try" in a while-loop also calls "ldap_search_ext_s" in this loop. This calls returns LDAP_SUCCESS (otherwise an error would be logged) and overwrites the flag "rc". After this has happend once, the function "another..." should immediately return, as this flags value is not equal LDAP_SERVER_DOWN. So there should NO messages "smbldap_open: already connected to the LDAP server" been generated.......????????

I give up at this point.....
Thanks in advance
J. Hergeth
Comment 3 Volker Lendecke 2007-02-09 15:01:44 UTC
Created attachment 2284 [details]
Proposed patch

The attached patch is against 3.0.24.

Volker
Comment 4 Volker Lendecke 2007-02-09 15:02:20 UTC
Marking as fixed with the attached patch. Please re-open if the patch does not fix it for you.

Thanks!

Volker
Comment 5 Volker Lendecke 2007-02-09 15:28:33 UTC
Created attachment 2285 [details]
Revised patch

Functionally the same, fixes a compile problem on quite a few platforms. On my SuSE 10.1 the old version worked fine, but the build farm told me different :-)

Volker