Bug 43144 - Samba: Multiple issues (4.1)
Samba: Multiple issues (4.1)
Status: CLOSED FIXED
Product: UCS
Classification: Unclassified
Component: Security updates
UCS 4.1
Other Linux
: P1 normal (vote)
: UCS 4.1-4-errata
Assigned To: Arvid Requate
Felix Botner
:
: 43132 (view as bug list)
Depends on:
Blocks: 43145
  Show dependency treegraph
 
Reported: 2016-12-09 11:18 CET by Arvid Requate
Modified: 2016-12-19 14:43 CET (History)
1 user (show)

See Also:
What kind of report is it?: Security Issue
What type of bug is this?: ---
Who will be affected by this bug?: ---
How will those affected feel about the bug?: ---
User Pain:
Enterprise Customer affected?:
School Customer affected?:
ISV affected?:
Waiting Support:
Ticket number:
Bug group (optional):
Max CVSS v3 score: 8.1 CVSS:3.0/AV:N/AC:H/PR:N/UI:N/S:U/C:H/I:H/A:H


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Arvid Requate univentionstaff 2016-12-09 11:18:30 CET
A security update for Samba is planned for Monday, December 19:

* NDR Parsing ndr_pull_dnsp_name Heap-based Buffer Overflow Remote Code Execution Vulnerability (CVE-2016-2123)

* Unconditional privilege delegation to Kerberos servers in trusted realms (CVE-2016-2125)

* Flaws in Kerberos PAC validation can trigger privilege elevation (CVE-2016-2126)
Comment 1 Arvid Requate univentionstaff 2016-12-12 20:41:39 CET
I've re-built samba with the patches to 4.5.2 and 4.5.3. Initial tests looked good. The advisory doesn't mention any details yet.
Comment 2 Arvid Requate univentionstaff 2016-12-12 20:41:45 CET
*** Bug 43132 has been marked as a duplicate of this bug. ***
Comment 3 Felix Botner univentionstaff 2016-12-13 17:04:39 CET
OK - patches
OK - samba version 4.5-3

OK - window client join (win7, win8)
OK - windows logon
OK - univention-s4search, drs repl
OK - kerberos
OK - GPO's
OK - share access

TODO
 update
 jenkins tests
Comment 4 Felix Botner univentionstaff 2016-12-14 11:34:39 CET
jenkins tests look good, but there is a problem with the update

UCS 4.1-4 master with samba4, then i updated to the new samba packages. After that univention-s4search fails

-> univention-s4search 
Failed to connect to ldap URL 'ldaps://master.four.test' - LDAP client internal error: NT_STATUS_CONNECTION_REFUSED
Failed to connect to 'ldaps://master.four.test' with backend 'ldaps': (null)
Failed to connect to ldaps://master.four.test - (null)

even if i wait 1h, univention-s4search fails

smbclient works
-> smbclient //master/sysvol -UAdministrator
Enter Administrator's password: 
Domain=[FOUR] OS=[Windows 6.1] Server=[Samba 4.5.3-Debian]
smb: \>


after samba restart, univention-s4search works
Comment 5 Arvid Requate univentionstaff 2016-12-14 12:24:43 CET
Yes, ldbsearch only works against localhost, not against the host IP, strange. smbclient works on both interfaces though.
Comment 6 Felix Botner univentionstaff 2016-12-14 14:17:48 CET
I can reproduce t

[2016/12/14 13:59:13.122929,  3, pid=16154, effective(0, 0), real(0, 0)] ../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
  Kerberos: TGS-REQ authtime: 2016-12-14T13:59:12 starttime: 2016-12-14T13:59:13 endtime: 2016-12-14T23:59:12 renew till: unset
[2016/12/14 13:59:13.127615,  3, pid=16154, effective(0, 0), real(0, 0)] ../source4/smbd/service_stream.c:66(stream_terminate_connection)
  Terminating connection - 'kdc_tcp_call_loop: tstream_read_pdu_blob_recv() - NT_STATUS_CONNECTION_DISCONNECTED'
[2016/12/14 13:59:13.127692,  3, pid=16154, effective(0, 0), real(0, 0)] ../source4/smbd/process_single.c:114(single_terminate)
  single_terminate: reason[kdc_tcp_call_loop: tstream_read_pdu_blob_recv() - NT_STATUS_CONNECTION_DISCONNECTED]
[2016/12/14 13:59:13.127792, 10, pid=16154, effective(0, 0), real(0, 0)] ../source3/lib/messages_dgm_ref.c:142(msg_dgm_ref_destructor)
  msg_dgm_ref_destructor: refs=0x562a679e2ef0
[2016/12/14 13:59:13.816622,  4, pid=16152, effective(0, 0), real(0, 0)] ../source4/lib/socket/interface.c:121(add_interface)
  added interface lo ip=::1 bcast= netmask=ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff
[2016/12/14 13:59:13.816795,  4, pid=16152, effective(0, 0), real(0, 0)] ../source4/lib/socket/interface.c:121(add_interface)
  added interface lo ip=127.0.0.1 bcast=127.255.255.255 netmask=255.0.0.0
[2016/12/14 13:59:13.817224,  3, pid=16152, effective(0, 0), real(0, 0)] ../lib/util/util_net.c:256(interpret_string_addr_internal)
  interpret_string_addr_internal: getaddrinfo failed for name eth0 (flags 32) [Name or service not known]
[2016/12/14 13:59:13.817306,  2, pid=16152, effective(0, 0), real(0, 0)] ../source4/lib/socket/interface.c:195(interpret_interface)
  interpret_interface: Can't find address for eth0

debug=10 -> "getaddrinfo failed for name eth0"
Comment 7 Felix Botner univentionstaff 2016-12-14 14:18:11 CET
(In reply to Felix Botner from comment #6)
> I can reproduce t
> 
> [2016/12/14 13:59:13.122929,  3, pid=16154, effective(0, 0), real(0, 0)]
> ../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
>   Kerberos: TGS-REQ authtime: 2016-12-14T13:59:12 starttime:
> 2016-12-14T13:59:13 endtime: 2016-12-14T23:59:12 renew till: unset
> [2016/12/14 13:59:13.127615,  3, pid=16154, effective(0, 0), real(0, 0)]
> ../source4/smbd/service_stream.c:66(stream_terminate_connection)
>   Terminating connection - 'kdc_tcp_call_loop: tstream_read_pdu_blob_recv()
> - NT_STATUS_CONNECTION_DISCONNECTED'
> [2016/12/14 13:59:13.127692,  3, pid=16154, effective(0, 0), real(0, 0)]
> ../source4/smbd/process_single.c:114(single_terminate)
>   single_terminate: reason[kdc_tcp_call_loop: tstream_read_pdu_blob_recv() -
> NT_STATUS_CONNECTION_DISCONNECTED]
> [2016/12/14 13:59:13.127792, 10, pid=16154, effective(0, 0), real(0, 0)]
> ../source3/lib/messages_dgm_ref.c:142(msg_dgm_ref_destructor)
>   msg_dgm_ref_destructor: refs=0x562a679e2ef0
> [2016/12/14 13:59:13.816622,  4, pid=16152, effective(0, 0), real(0, 0)]
> ../source4/lib/socket/interface.c:121(add_interface)
>   added interface lo ip=::1 bcast=
> netmask=ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff
> [2016/12/14 13:59:13.816795,  4, pid=16152, effective(0, 0), real(0, 0)]
> ../source4/lib/socket/interface.c:121(add_interface)
>   added interface lo ip=127.0.0.1 bcast=127.255.255.255 netmask=255.0.0.0
> [2016/12/14 13:59:13.817224,  3, pid=16152, effective(0, 0), real(0, 0)]
> ../lib/util/util_net.c:256(interpret_string_addr_internal)
>   interpret_string_addr_internal: getaddrinfo failed for name eth0 (flags
> 32) [Name or service not known]
> [2016/12/14 13:59:13.817306,  2, pid=16152, effective(0, 0), real(0, 0)]
> ../source4/lib/socket/interface.c:195(interpret_interface)
>   interpret_interface: Can't find address for eth0
> 
> debug=10 -> "getaddrinfo failed for name eth0"

this is the restart during the update
Comment 8 Arvid Requate univentionstaff 2016-12-14 20:17:49 CET
I've added some debugging messages to Samba.
Bug even in your environment I cannot reproduce it, even though I also used "apt-get update; apt-get dselect-upgrade; apt-get dist-upgrade" to update.

If you try it again, please set the samba/debug/level at least to 2 before updating.
Comment 9 Arvid Requate univentionstaff 2016-12-15 14:44:39 CET
We also have a separate report for winbindd (samba3) failing to start in UCS@school Jenkins, but only in the 4.0 to 4.1 updated ImportTests:

UCSschool 4.0 to 4.1 Singleserver/ImportTests=ImportTests,SambaVersion=s3/ws/autotest-205-ucsschool-singleserver-s3.log
===========================================================================
The following packages will be upgraded:
 univention-directory-manager-tools,python-univention-directory-manager,python-univention-directory-manager-cli,python-univention-connector-s4,samba-vfs-modules,samba-dsdb-modules,slapd,ldap-utils,libldap-2.4-2,winbind,libwbclient0,samba,samba-common-bin,smbclient,samba-common,libsmbclient,python-samba,samba-libs,univention-kernel-image,linux-libc-dev,univention-management-console-module-join,univention-join,univention-ssl,univention-mail-postfix
Starting package upgrade                                ERROR: update failed. Please check /var/log/univention/updater.log
===========================================================================
and ws/updater.log shows:
===========================================================================
Vorbereitung zum Ersetzen von winbind 2:4.5.1-1.848.201611070734 (durch .../winbind_2%3a4.5.1-1.849.201612142005_amd64.deb) ...
[...]
ucs-school-umc-wizards (8.0.0-14.149.201611171707) wird eingerichtet ...
Calling joinscript 38ucs-school-umc-wizards.inst ...
2016-12-14 19:11:23.208427560-05:00 (in joinscript_init)
[...]
samba (2:4.5.1-1.849.201612142005) wird eingerichtet ...
Starting SMB/CIFS daemon: smbd.
Starting NetBIOS name server: nmbd.
Samba is not configured as AD DC.
winbind (2:4.5.1-1.849.201612142005) wird eingerichtet ...
Starting the Winbind daemon: winbind failed!
invoke-rc.d: initscript winbind, action "start" failed.
dpkg: Fehler beim Bearbeiten von winbind (--configure):
 Unterprozess installiertes post-installation-Skript gab den Fehlerwert 1 zurück
[...]
univention-join (8.0.4-7.521.201612071726) wird eingerichtet ...
File: /etc/logrotate.d/univention-join
Calling joinscript 20univention-join.inst ...
2016-12-14 19:12:06.738252002-05:00 (in joinscript_init)
===========================================================================

So this happens between 19:11:23.208427560-05:00 and 19:12:06.738252002-05:00.

In that time range log.winbindd shows *no* output (last entry before is at 19:19:04.272473 and the next after is at 19:21:15.880862). To compare, log.smbd shows some of our new debug output in that time range. So this looks like a different issue than the "getaddrinfo failed for name eth0" in Comment 6.

Daniel noted that there is a slapd restart visible in syslog at (about) that time, but the autotest-205-ucsschool-singleserver-s3.log shows that the winbind start fails again two times after that, so it's unlikely that there is any correlation.

I'm just spinning up a Jenkins test to see what's going on.
Comment 10 Arvid Requate univentionstaff 2016-12-15 20:34:05 CET
I think that the update of univention-basefiles is causing this. The univention-basefiles.postinst seems to run shortly after the samba.postinst and it seems to ifdown/up eth0 somehow.

This is the full story of my research:

These two messages have also been reported once in Ubuntu and there it was due to networkmanager not having the interface up in time for samba  https://bugs.launchpad.net/ubuntu/+source/samba/+bug/836849 :

*  interpret_string_addr_internal: getaddrinfo failed for name eth0 (flags 32) [Name or service not known]

*  interpret_interface: Can't find address for eth0


And there you go, in Felix VM-snapshot I find these messages in syslog:

=============================================================================
Dec 14 13:59:12 master named[9930]: received control channel command 'reload'
[...]
Dec 14 13:59:13 master ntpd[6293]: Deleting interface #7 eth0, fe80::5054:ff:feb0:56d7#123, interface stats: received=0, sent=0, dropped=0, active_time=1225 secs
Dec 14 13:59:13 master ntpd[6293]: Deleting interface #3 eth0, 10.200.7.80#123, interface stats: received=0, sent=0, dropped=0, active_time=1225 secs
Dec 14 13:59:13 master ntpd[6293]: peers refreshed
=============================================================================

So at least ntpd also noticed an interface change in the same second.

Let's look at /var/log/dpkg.log, shall we?
=============================================================================
2016-12-14 13:59:05 status unpacked samba:amd64 2:4.5.1-1.849.201612121623
2016-12-14 13:59:05 status half-configured samba:amd64 2:4.5.1-1.849.201612121623
2016-12-14 13:59:06 status installed samba:amd64 2:4.5.1-1.849.201612121623
[...]
2016-12-14 13:59:07 status unpacked univention-base-files:all 5.0.1-6.222.201612051558
2016-12-14 13:59:07 status half-configured univention-base-files:all 5.0.1-6.222.201612051558
2016-12-14 13:59:28 status triggers-awaited univention-base-files:all 5.0.1-6.222.201612051558
=============================================================================

So let's look at univention-base-files.postinst. There is a call to

 univention-config-registry register univention-base-files

When I run that on my machine, I get:
=============================================================================
File: /etc/modprobe.d/vmgfx.conf
Multifile: /etc/network/interfaces
Reloading bind9 daemon: ...samba4...done.
Restarting Name Service Cache Daemon: nscd.
Reloading bind9 daemon: ...samba4...done.
Stopping univention-s4-connector daemon.
done.
Starting univention-s4-connector daemon.
done.
Reloading bind9 daemon: ...samba4...done.
Reloading bind9 daemon: ...samba4...done.
File: /etc/dhcp/dhclient.conf
Restarting Name Service Cache Daemon: nscd.
Restarting Univention Management Console Server.
done.
Reloading bind9 daemon: ...samba4...done.
Reloading bind9 daemon: ...samba4...done.
File: /etc/rsyslog.conf
=============================================================================

Ok, let's stat the files in Felix VM-snapshot to narrow down the time interval:
=============================================================================
root@master:~# stat /etc/modprobe.d/vmgfx.conf
  Datei: „/etc/modprobe.d/vmgfx.conf“
  Größe: 653            Blöcke: 8          EA Block: 4096   reguläre Datei
Gerät: fd00h/64768d     Inode: 2355742     Verknüpfungen: 1
Zugriff: (0644/-rw-r--r--)  Uid: (    0/    root)   Gid: (    0/    root)
Zugriff    : 2016-12-14 13:59:24.006261000 +0100
Modifiziert: 2016-12-14 13:59:11.146261000 +0100
Geändert   : 2016-12-14 13:59:11.146261000 +0100
 Geburt    : -
root@master:~# stat /etc/network/interfaces
  Datei: „/etc/network/interfaces“
  Größe: 684            Blöcke: 8          EA Block: 4096   reguläre Datei
Gerät: fd00h/64768d     Inode: 2355826     Verknüpfungen: 1
Zugriff: (0644/-rw-r--r--)  Uid: (    0/    root)   Gid: (    0/    root)
Zugriff    : 2016-12-14 13:59:18.250261000 +0100
Modifiziert: 2016-12-14 13:59:18.242261000 +0100
Geändert   : 2016-12-14 13:59:18.242261000 +0100
 Geburt    : -
root@master:~# stat /etc/rsyslog.conf
  Datei: „/etc/rsyslog.conf“
  Größe: 3413           Blöcke: 8          EA Block: 4096   reguläre Datei
Gerät: fd00h/64768d     Inode: 2355931     Verknüpfungen: 1
Zugriff: (0644/-rw-r--r--)  Uid: (    0/    root)   Gid: (    0/    root)
Zugriff    : 2016-12-14 13:59:23.822261000 +0100
Modifiziert: 2016-12-14 13:59:23.994261000 +0100
Geändert   : 2016-12-14 13:59:23.994261000 +0100
 Geburt    : -
=============================================================================

From all of this, I have the impression that "something" is causing temporary interruption for eth0. Bug 32481 might be related.

Apart from that, it's a bit surprising that the Samba daemons are taking so long to start up, that univention-basefiles has enough time to interfere:

=============================================================================
[2016/12/14 13:59:06.488595,  0, pid=16096, effective(0, 0), real(0, 0)] ../source4/smbd/server.c:372(binary_smbd_main)
  samba version 4.5.3-Debian started.
  Copyright Andrew Tridgell and the Samba Team 1992-2016
=============================================================================

That's 6.64 seconds between start of samba and interface bind of the samba ldap_server process. Note that each of the 12 samba services (plus the forked smbd and winbind processes probably) do their own interface detection. Each of them could be hit by this!! The possible error scenarios are endless.

All of this matches with my experience when trying to reproduce this in Felix VM: Two times, when I used "apt-get update; apt-get dselect-upgrade; apt-get dist-upgrade" to update, my ssh-connection to that VM terminated in the middle of the update. Since I was connected from home office via VPN I didn't think too much about it, but now it seems related.

Also it matches my experience with UCS-updates of one of my VMs, where the SSH-connection would often terminate in the middle of a release update (univention-upgrade run without screen).
Comment 11 Arvid Requate univentionstaff 2016-12-15 21:24:43 CET
Comment 10 refers to to the univention-s4search issue reported by Felix in Comment 6.

I'd say we can only do one thing now to avoid this during this update: adjust samba.postinst to sleep 10 seconds after the start of the daemons. I think I will even put it permanently, without any version checks, because waiting 10 seconds during update is *much* better than running into this randomly at some later errata update.



Now about the winbindd issue of Comment 9: I was able to reproduce that in the Samba3 UCS@school singleserver Jenkins test. Basically it's unrelated and I opened Bug 43192 for it. But we need a workaround for it. I've adjusted winbind.postinst to stop any running winbinds before the DEBHELPER block which adds the winbind start.

The package is compiling and the advisory is updated.
Comment 12 Arvid Requate univentionstaff 2016-12-15 21:31:57 CET
I've opened Bug 43193 for Comment 10, this needs to be fixed.
Comment 13 Felix Botner univentionstaff 2016-12-16 12:58:16 CET
FAIL - samba postinst, 
we now wait 10s in samba.postinst, i don't understand this. 
I can't reproduce this anymore, but as it happened, i could have waited for hours and the situation would not have changed, only a samba restart helped?


OK - windbind, postinst stops windbindd before starting
Comment 14 Arvid Requate univentionstaff 2016-12-16 15:31:38 CET
Come on, you read Comment 10, didn't you? Look into the updater.log of your snapshot, you see that samba.postinst runs and after that univention-base-files.postinst runs, which runs "univention-config-registry register univention-base-files". During that command eth0 when down for a short time and this cooincided with the start of the Samba ldap_server process.

Now the samba.postinst waits 10 seconds after the samba-ad-dc start to avoid the ensuing eth0 if-up/down happening shortly after.

My solution is not curing the problem after it happened (as in your case),
it's avoiding it in the first place. If you disagree open another bug for that.
Comment 15 Arvid Requate univentionstaff 2016-12-16 15:42:59 CET
> Look into the updater.log of your snapshot

Ah, actually you cannot, because you didn't use univention-upgrade, but apt-get dist-upgrade instead, which made debugging this unnecessary hard. Please avoid that by any means.
Comment 16 Philipp Hahn univentionstaff 2016-12-16 17:04:12 CET
(In reply to Arvid Requate from comment #15)
> > Look into the updater.log of your snapshot
> 
> Ah, actually you cannot, because you didn't use univention-upgrade, but
> apt-get dist-upgrade instead, which made debugging this unnecessary hard.
> Please avoid that by any means.

Ever heard of /var/log/apt/term.log?
Gbb onq HPF hfrf "lrg nabgure iraqbe fcrpvsvp fbyhgvba"...
Comment 17 Felix Botner univentionstaff 2016-12-16 17:18:27 CET
ok, ok, finally i got it ...
sleep in the samba.postinst should buy the daemons enough time to start properly, before a univention-base-files update can mess with the interfaces
Comment 18 Arvid Requate univentionstaff 2016-12-19 11:49:42 CET
> Ever heard of /var/log/apt/term.log?

Thanks, much appreciated.

> Gbb onq HPF hfrf "lrg nabgure iraqbe fcrpvsvp fbyhgvba"..

Jryy, gb or snve gurl ner whfg n jenccre sbe gur naablvat fcyvg orgjrra ncg-trg hcqngr naq ncg-trg [qvfg-hctenqr|vafgnyy]. Gurl pbzr va unaql.
Comment 19 Arvid Requate univentionstaff 2016-12-19 12:45:29 CET
<http://errata.software-univention.de/ucs/4.1/360.html>