samba - Jul 2019 - samba 4.8 client and 4.9 AD DC: Reducing LDAP page size from 1000 to 500 due to IO_TIMEOUT

Hello,

I have an issue as stated in topic. My samba 4.8.3 file server, which is AD
member frequently shows winbind errors (pasted below). From user
perspective it seems to work fine, but I'm worried that I have something
misconfigured and in the long run, I might run into some errors.

My AD DC are running on samba 4.9.x (two of them), compiled from source
with BIND as DNS backend (running on the DC's)
Both file server and DC are on centos, both are virtual machines running on
same host.

It seems that every time that samba using file server account tries to
authenticate it logs errors, but eventually succeeds. Below i'm pasting
entries from samba file server and from my dc1.
Looking at timestamps it seems that first samba client announces failure
then some mere milliseconds later finally succeeds. And it repeats itself
every 60 minutes or so (between 30 to 90 minutes it seems)

I have had similar error, also unsolved on another samba file server
(4.9.6, compiled from source), and that server had this error exactly every
60 minutes. Also no noticeable issues for the users.

Hopefully someone can give me some pointers, where to look for potential
causes of this error.

Below my configuration and log entries from file server and domain
controller.

My settings are pretty basic, I've rechecked:
/etc/resolv.conf (points to DNS on AD DC)
/etc/nsswitch.conf (files winbind for passwd and groups)
/etc/krb5.conf is according to samba wiki for AD DC and samba member

my smb.conf for fileserver is:

[global]
       netbios name = MYFILESERVER
       security = ADS
       workgroup = MYDOMAIN
       realm = MY.REALM

       log level = 1 winbind:5
       log file = /var/log/samba/%m.log
        max log size = 2000
        logging = syslog at 2 file
       idmap config *:backend = tdb
       idmap config *:range = 2000-7000

       idmap config MYDOMAIN:backend = rid
       idmap config MYDOMAIN:range = 100000-110000

        winbind enum users = no
        winbind enum groups = no
        winbind nested groups = yes
        winbind expand groups = 3
        winbind refresh tickets = yes
        winbind use default domain = no
        winbind offline logon = yes

        template shell = /bin/bash
        template homedir = /home/%U@%D

        kerberos method = secrets and keytab

        load printers = no
        printing = bsd
        printcap name = /dev/null
        disable spoolss = yes
        vfs objects = acl_xattr full_audit recycle

        full_audit:prefix = %u|%I|%M|%S
        full_audit:failure = connect
        full_audit:success =  mkdir rmdir write rename pwrite unlink
        full_audit:priority = NOTICE

        recycle:repository = .recycle
        recycle:keeptree = yes
        recycle:versions = yes
        recycle:touch_mtime = yes
        recycle:exclude = *.tmp, *.TMP
        recycle:exclude_dir = .recycle
        recycle:maxsize = 1073741824


smb.conf for DC:
[global]
        netbios name = DC1
        realm = MY.REALM
        workgroup = MYDOMAIN
        server role = active directory domain controller
        idmap_ldb:use rfc2307 = yes

        load printers = no
        printing = bsd
        printcap name = /dev/null
        disable spoolss = yes


        log level = 1 auth_audit:5 auth_json_audit:5 smb:2 winbind:5
        log file = /var/log/samba/samba.log.%m
        #logging = file
        logging = syslog at 3
        max log size = 10000

        allow dns updates = secure

        server services = -dns

        tls enabled = yes
        tls keyfile = /usr/local/samba/private/tls/dc1.key.pem
        tls certfile = /usr/local/samba/private/tls/dc1.cert.pem
        tls cafile = /usr/local/samba/private/tls/ca-chain.cert.pem

        apply group policies = yes


winbind log from file server:

[2019/07/16 16:45:38.693115,  1]
../source3/libads/ldap_utils.c:93(ads_do_search_retry_internal)
  Reducing LDAP page size from 1000 to 500 due to IO_TIMEOUT
[2019/07/16 16:45:38.758657,  1]
../source3/libads/ldap_utils.c:111(ads_do_search_retry_internal)
  ads_search_retry: failed to reconnect (No logon servers are currently
available to service the logon request.)

domain controller authentication log:
dc1 samba[150641]:
JSON Authentication: {"timestamp":
"2019-07-16T16:45:38.816108+0200",
"type": "Authentication",
"Authentication": {"version": {"major": 1,
"minor": 0},
"status": "NT_STATUS_OK", "localAddress": null,
"remoteAddress":
"ipv4:192.168.xx.xx:37442",
"serviceDescription": "Kerberos KDC",
"authDescription": "ENC-TS Pre-authentication",
"clientDomain": null,
"clientAccount": "MYFILESERVER$@MY.REALM",
"workstation": null,
"becameAccount": "MYFILESERVER$",
"becameDomain": "MYDOMAIN", "becameSid":
"S-1-5-21-SOME-SID-NUMBER",
"mappedAccount": "MYFILESERVER$", "mappedDomain":
"MYDOMAIN",
"netlogonComputer": null, "netlogonTrustAccount": null,
"netlogonNegotiateFlags": "0x00000000",
"netlogonSecureChannelType": 0,
"netlogonTrustAccountSid": null, "passwordType":
"arcfour-hmac-md5",
"duration": 6660}}

Regards,
Kacper

On 16/07/2019 16:31, Kacper Wirski via samba wrote:
> Hello,
>
> I have an issue as stated in topic. My samba 4.8.3 file server, which is AD
> member frequently shows winbind errors (pasted below). From user
> perspective it seems to work fine, but I'm worried that I have
something
> misconfigured and in the long run, I might run into some errors.
>
> My AD DC are running on samba 4.9.x (two of them), compiled from source
> with BIND as DNS backend (running on the DC's)
> Both file server and DC are on centos, both are virtual machines running on
> same host.
>
> It seems that every time that samba using file server account tries to
> authenticate it logs errors, but eventually succeeds. Below i'm pasting
> entries from samba file server and from my dc1.
> Looking at timestamps it seems that first samba client announces failure
> then some mere milliseconds later finally succeeds. And it repeats itself
> every 60 minutes or so (between 30 to 90 minutes it seems)
>
> I have had similar error, also unsolved on another samba file server
> (4.9.6, compiled from source), and that server had this error exactly every
> 60 minutes. Also no noticeable issues for the users.
>
> Hopefully someone can give me some pointers, where to look for potential
> causes of this error.
>
> Below my configuration and log entries from file server and domain
> controller.
>
> My settings are pretty basic, I've rechecked:
> /etc/resolv.conf (points to DNS on AD DC)
> /etc/nsswitch.conf (files winbind for passwd and groups)
> /etc/krb5.conf is according to samba wiki for AD DC and samba member
>
> my smb.conf for fileserver is:
>
> [global]
>         netbios name = MYFILESERVER
>         security = ADS
>         workgroup = MYDOMAIN
>         realm = MY.REALM
>
>         log level = 1 winbind:5
>         log file = /var/log/samba/%m.log
>          max log size = 2000
>          logging = syslog at 2 file
>         idmap config *:backend = tdb
>         idmap config *:range = 2000-7000
>
>         idmap config MYDOMAIN:backend = rid
>         idmap config MYDOMAIN:range = 100000-110000
>
>          winbind enum users = no
>          winbind enum groups = no
>          winbind nested groups = yes
>          winbind expand groups = 3
>          winbind refresh tickets = yes
>          winbind use default domain = no
>          winbind offline logon = yes
>
>          template shell = /bin/bash
>          template homedir = /home/%U@%D
>
>          kerberos method = secrets and keytab
>
>          load printers = no
>          printing = bsd
>          printcap name = /dev/null
>          disable spoolss = yes
>          vfs objects = acl_xattr full_audit recycle
>
>          full_audit:prefix = %u|%I|%M|%S
>          full_audit:failure = connect
>          full_audit:success =  mkdir rmdir write rename pwrite unlink
>          full_audit:priority = NOTICE
>
>          recycle:repository = .recycle
>          recycle:keeptree = yes
>          recycle:versions = yes
>          recycle:touch_mtime = yes
>          recycle:exclude = *.tmp, *.TMP
>          recycle:exclude_dir = .recycle
>          recycle:maxsize = 1073741824
>
>
> smb.conf for DC:
> [global]
>          netbios name = DC1
>          realm = MY.REALM
>          workgroup = MYDOMAIN
>          server role = active directory domain controller
>          idmap_ldb:use rfc2307 = yes
>
>          load printers = no
>          printing = bsd
>          printcap name = /dev/null
>          disable spoolss = yes
>
>
>          log level = 1 auth_audit:5 auth_json_audit:5 smb:2 winbind:5
>          log file = /var/log/samba/samba.log.%m
>          #logging = file
>          logging = syslog at 3
>          max log size = 10000
>
>          allow dns updates = secure
>
>          server services = -dns
>
>          tls enabled = yes
>          tls keyfile = /usr/local/samba/private/tls/dc1.key.pem
>          tls certfile = /usr/local/samba/private/tls/dc1.cert.pem
>          tls cafile = /usr/local/samba/private/tls/ca-chain.cert.pem
>
>          apply group policies = yes
>
>
> winbind log from file server:
>
> [2019/07/16 16:45:38.693115,  1]
> ../source3/libads/ldap_utils.c:93(ads_do_search_retry_internal)
>    Reducing LDAP page size from 1000 to 500 due to IO_TIMEOUT
> [2019/07/16 16:45:38.758657,  1]
> ../source3/libads/ldap_utils.c:111(ads_do_search_retry_internal)
>    ads_search_retry: failed to reconnect (No logon servers are currently
> available to service the logon request.)
>
> domain controller authentication log:
> dc1 samba[150641]:
> JSON Authentication: {"timestamp":
"2019-07-16T16:45:38.816108+0200",
> "type": "Authentication",
> "Authentication": {"version": {"major": 1,
"minor": 0},
> "status": "NT_STATUS_OK", "localAddress":
null, "remoteAddress":
> "ipv4:192.168.xx.xx:37442",
> "serviceDescription": "Kerberos KDC",
> "authDescription": "ENC-TS Pre-authentication",
"clientDomain": null,
> "clientAccount": "MYFILESERVER$@MY.REALM",
"workstation": null,
> "becameAccount": "MYFILESERVER$",
> "becameDomain": "MYDOMAIN", "becameSid":
"S-1-5-21-SOME-SID-NUMBER",
> "mappedAccount": "MYFILESERVER$",
"mappedDomain": "MYDOMAIN",
> "netlogonComputer": null, "netlogonTrustAccount": null,
> "netlogonNegotiateFlags": "0x00000000",
"netlogonSecureChannelType": 0,
> "netlogonTrustAccountSid": null, "passwordType":
"arcfour-hmac-md5",
> "duration": 6660}}
>
> Regards,
> Kacper
Are you having actual problems on the Unix domain member ?

If not, why do have this in smb.conf:

log level = 1 winbind:5

I would change it to:

log level = 0

The message is coming from this block of code:

 ??? ??? ??? DEBUG(1, ("Reducing LDAP page size from %d to %d due to 
IO_TIMEOUT\n",
 ??? ??? ??? ??? ? ads->config.ldap_page_size, new_page_size));

As you can see, it is just a debug message, that is printed if log level 
is set to '1' or above.

Rowland

Hello,

Thank You for prompt reply!

As I stated, I don't have any issues that I'm aware of, but this file
server is new in my infrastructure and I was worried that something is
incorrect. I set minimal logging as a habit, and I bumped winbind recently
to maybe see something that would help me solve this problem.

What about this:
ads_search_retry: failed to reconnect (No logon servers are currently
available to service the logon request.)

is it "normal" in this context? That was the part that worried me,
this and
perhaps some performance issue (IO_TIMEOUT).

Regards,
Kacper

wt., 16 lip 2019 o 17:54 Rowland penny via samba <samba at
lists.samba.org>
napisa?(a):
> On 16/07/2019 16:31, Kacper Wirski via samba wrote:
> > Hello,
> >
> > I have an issue as stated in topic. My samba 4.8.3 file server, which
is
> AD
> > member frequently shows winbind errors (pasted below). From user
> > perspective it seems to work fine, but I'm worried that I have
something
> > misconfigured and in the long run, I might run into some errors.
> >
> > My AD DC are running on samba 4.9.x (two of them), compiled from
source
> > with BIND as DNS backend (running on the DC's)
> > Both file server and DC are on centos, both are virtual machines
running
> on
> > same host.
> >
> > It seems that every time that samba using file server account tries to
> > authenticate it logs errors, but eventually succeeds. Below i'm
pasting
> > entries from samba file server and from my dc1.
> > Looking at timestamps it seems that first samba client announces
failure
> > then some mere milliseconds later finally succeeds. And it repeats
itself
> > every 60 minutes or so (between 30 to 90 minutes it seems)
> >
> > I have had similar error, also unsolved on another samba file server
> > (4.9.6, compiled from source), and that server had this error exactly
> every
> > 60 minutes. Also no noticeable issues for the users.
> >
> > Hopefully someone can give me some pointers, where to look for
potential
> > causes of this error.
> >
> > Below my configuration and log entries from file server and domain
> > controller.
> >
> > My settings are pretty basic, I've rechecked:
> > /etc/resolv.conf (points to DNS on AD DC)
> > /etc/nsswitch.conf (files winbind for passwd and groups)
> > /etc/krb5.conf is according to samba wiki for AD DC and samba member
> >
> > my smb.conf for fileserver is:
> >
> > [global]
> >         netbios name = MYFILESERVER
> >         security = ADS
> >         workgroup = MYDOMAIN
> >         realm = MY.REALM
> >
> >         log level = 1 winbind:5
> >         log file = /var/log/samba/%m.log
> >          max log size = 2000
> >          logging = syslog at 2 file
> >         idmap config *:backend = tdb
> >         idmap config *:range = 2000-7000
> >
> >         idmap config MYDOMAIN:backend = rid
> >         idmap config MYDOMAIN:range = 100000-110000
> >
> >          winbind enum users = no
> >          winbind enum groups = no
> >          winbind nested groups = yes
> >          winbind expand groups = 3
> >          winbind refresh tickets = yes
> >          winbind use default domain = no
> >          winbind offline logon = yes
> >
> >          template shell = /bin/bash
> >          template homedir = /home/%U@%D
> >
> >          kerberos method = secrets and keytab
> >
> >          load printers = no
> >          printing = bsd
> >          printcap name = /dev/null
> >          disable spoolss = yes
> >          vfs objects = acl_xattr full_audit recycle
> >
> >          full_audit:prefix = %u|%I|%M|%S
> >          full_audit:failure = connect
> >          full_audit:success =  mkdir rmdir write rename pwrite unlink
> >          full_audit:priority = NOTICE
> >
> >          recycle:repository = .recycle
> >          recycle:keeptree = yes
> >          recycle:versions = yes
> >          recycle:touch_mtime = yes
> >          recycle:exclude = *.tmp, *.TMP
> >          recycle:exclude_dir = .recycle
> >          recycle:maxsize = 1073741824
> >
> >
> > smb.conf for DC:
> > [global]
> >          netbios name = DC1
> >          realm = MY.REALM
> >          workgroup = MYDOMAIN
> >          server role = active directory domain controller
> >          idmap_ldb:use rfc2307 = yes
> >
> >          load printers = no
> >          printing = bsd
> >          printcap name = /dev/null
> >          disable spoolss = yes
> >
> >
> >          log level = 1 auth_audit:5 auth_json_audit:5 smb:2 winbind:5
> >          log file = /var/log/samba/samba.log.%m
> >          #logging = file
> >          logging = syslog at 3
> >          max log size = 10000
> >
> >          allow dns updates = secure
> >
> >          server services = -dns
> >
> >          tls enabled = yes
> >          tls keyfile = /usr/local/samba/private/tls/dc1.key.pem
> >          tls certfile = /usr/local/samba/private/tls/dc1.cert.pem
> >          tls cafile = /usr/local/samba/private/tls/ca-chain.cert.pem
> >
> >          apply group policies = yes
> >
> >
> > winbind log from file server:
> >
> > [2019/07/16 16:45:38.693115,  1]
> > ../source3/libads/ldap_utils.c:93(ads_do_search_retry_internal)
> >    Reducing LDAP page size from 1000 to 500 due to IO_TIMEOUT
> > [2019/07/16 16:45:38.758657,  1]
> > ../source3/libads/ldap_utils.c:111(ads_do_search_retry_internal)
> >    ads_search_retry: failed to reconnect (No logon servers are
currently
> > available to service the logon request.)
> >
> > domain controller authentication log:
> > dc1 samba[150641]:
> > JSON Authentication: {"timestamp":
"2019-07-16T16:45:38.816108+0200",
> > "type": "Authentication",
> > "Authentication": {"version": {"major":
1, "minor": 0},
> > "status": "NT_STATUS_OK",
"localAddress": null, "remoteAddress":
> > "ipv4:192.168.xx.xx:37442",
> > "serviceDescription": "Kerberos KDC",
> > "authDescription": "ENC-TS Pre-authentication",
"clientDomain": null,
> > "clientAccount": "MYFILESERVER$@MY.REALM",
"workstation": null,
> > "becameAccount": "MYFILESERVER$",
> > "becameDomain": "MYDOMAIN", "becameSid":
"S-1-5-21-SOME-SID-NUMBER",
> > "mappedAccount": "MYFILESERVER$",
"mappedDomain": "MYDOMAIN",
> > "netlogonComputer": null, "netlogonTrustAccount":
null,
> > "netlogonNegotiateFlags": "0x00000000",
"netlogonSecureChannelType": 0,
> > "netlogonTrustAccountSid": null, "passwordType":
"arcfour-hmac-md5",
> > "duration": 6660}}
> >
> > Regards,
> > Kacper
>
> Are you having actual problems on the Unix domain member ?
>
> If not, why do have this in smb.conf:
>
> log level = 1 winbind:5
>
> I would change it to:
>
> log level = 0
>
> The message is coming from this block of code:
>
>              DEBUG(1, ("Reducing LDAP page size from %d to %d due to
> IO_TIMEOUT\n",
>                    ads->config.ldap_page_size, new_page_size));
>
> As you can see, it is just a debug message, that is printed if log level
> is set to '1' or above.
>
> Rowland
>
>
> --
> To unsubscribe from this list go to the following URL and read the
> instructions:  https://lists.samba.org/mailman/options/samba
>