none
W10 Pro 1903 and Samba with Roaming Profiles: "We can't sign in to your account" RRS feed

  • Question

  • Hello,

    since the upgrade from W10 pro 1809 to 1903 roaming users can still logon, but they are 'greeted' with the message: "We can't sign in to your account", letting them know, that they are working with a temporary user profile only, and that their work will get lost, if they don't sign-off.

    The user profiles are handled by a samba server running in an NT4-Style DC Mode with "Single Label DNS Domain" on a Debian system.

    I had a look into the registry for ".bak" profiles, but there aren't any. so I think this is not the problem.

    As a test I created the new and clean empty user profile "zurbel" on the samba, however also this new user gets the same warning.

    The login with this user on to a system which is still on 1809 works flawless.

    A profile.V6 gets created and also the user's data get properly synced (back) to it's directory on the samba server.

    zurbel# ls -al profile.V6/
    total 836
    drwxr-xr-x 16 zurbel root    4096 Jun  4 19:27 .
    drwxr-xr-x  3 zurbel root    4096 Jun  4 19:12 ..
    drwxrwxr-x  2 zurbel guest   4096 Jun  4 19:24 3D Objects
    drwxrwxr-x  3 zurbel guest   4096 Jun  4 19:24 AppData
    drwxrwxr-x  2 zurbel guest   4096 Jun  4 19:24 Contacts
    drwxrwxr-x  2 zurbel guest   4096 Jun  4 19:24 Desktop
    drwxrwxr-x  2 zurbel guest   4096 Jun  4 19:24 Documents
    drwxrwxr-x  2 zurbel guest   4096 Jun  4 19:24 Downloads
    drwxrwxr-x  3 zurbel guest   4096 Jun  4 19:24 Favorites
    drwxrwxr-x  2 zurbel guest   4096 Jun  4 19:24 IntelGraphicsProfiles
    drwxrwxr-x  2 zurbel guest   4096 Jun  4 19:24 Links
    drwxrwxr-x  2 zurbel guest   4096 Jun  4 19:24 Music
    -rwxrwxr-x  1 zurbel guest 786432 Jun  4 19:27 NTUSER.DAT
    -rwxrwxr-x  1 zurbel guest    294 Jun  4 19:27 ntuser.ini
    drwxrwxr-x  4 zurbel guest   4096 Jun  4 19:24 Pictures
    drwxrwxr-x  2 zurbel guest   4096 Jun  4 19:24 Saved Games
    drwxrwxr-x  2 zurbel guest   4096 Jun  4 19:24 Searches
    drwxrwxr-x  2 zurbel guest   4096 Jun  4 19:24 Videos

    Does anybody have a hint how to fix this issue, pls.



    • Edited by odoll Saturday, June 8, 2019 12:53 PM typos
    Saturday, June 8, 2019 12:48 PM

All replies

  • Hello odoll,

    Once logged on from a Windows 10 1903 client and temporary profile, can the client access their roaming profile on the samba server or indeed any other shares and directories on the samba server?

    I was involved in another discussion with someone in this forum (https://social.technet.microsoft.com/Forums/en-US/9e7a4ce3-4690-4dbb-b2db-e17d7f29f9ad/windows-10-1903-cannot-connect-to-smb-share?forum=win10itprogeneral) and there seems to have been a minor enhancement to the Windows SMB implementation in 1903 that might cause be the cause of their problem - it might be affecting you too.

    Gary

    Saturday, June 8, 2019 1:16 PM
  • Hello Gary,

    thx for your reply.

    Yes, when the user's logged on with the temp profile, his home directory on the samba server is mapped (as usually) locally to the network drive with the letter Z:  [e.g. shown as "zurbel (\\share) (Z:)"] and he also has access to all other shares and it's data on the samba server.

    Saturday, June 8, 2019 3:15 PM
  • PS: Tried to logon as user zurbel and had a look into the Security log searching for error.

    I can see that the machine LAT is successfully authenticated:

    Log Name:      Security
    Source:        Microsoft-Windows-Security-Auditing
    Date:          08.06.2019 20:43:40
    Event ID:      5382
    Task Category: User Account Management
    Level:         Information
    Keywords:      Audit Success
    User:          N/A
    Computer:      LAT.DOMAIN.de
    Description:
    Vault credentials were read.
    
    Subject:
    	Security ID:		SYSTEM
    	Account Name:		LAT$
    	Account Domain:		DOMAIN
    	Logon ID:		0x3E7
    
    This event occurs when a user reads a stored vault credential.

    And user zurbel as well

    Log Name:      Security
    Source:        Microsoft-Windows-Security-Auditing
    Date:          08.06.2019 20:44:18
    Event ID:      5379
    Task Category: User Account Management
    Level:         Information
    Keywords:      Audit Success
    User:          N/A
    Computer:      LAT.DOMAIN.de
    Description:
    Credential Manager credentials were read.
    
    Subject:
    	Security ID:		DOMAIN\zurbel
    	Account Name:		zurbel
    	Account Domain:		DOMAIN
    	Logon ID:		0x148D54
    	Read Operation:		Enumerate Credentials
    
    This event occurs when a user performs a read operation on stored credentials in Credential Manager.

    However there are a lot of failures of the following kind:

    Log Name:      Security
    Source:        Microsoft-Windows-Security-Auditing
    Date:          08.06.2019 20:44:51
    Event ID:      5061
    Task Category: System Integrity
    Level:         Information
    Keywords:      Audit Failure
    User:          N/A
    Computer:      LAT.DOMAIN.de
    Description:
    Cryptographic operation.
    
    Subject:
    	Security ID:		DOMAIN\zurbel
    	Account Name:		zurbel
    	Account Domain:		DOMAIN
    	Logon ID:		0x148D54
    
    Cryptographic Parameters:
    	Provider Name:	Microsoft Software Key Storage Provider
    	Algorithm Name:	UNKNOWN
    	Key Name:	Microsoft Connected Devices Platform device certificate
    	Key Type:	User key.
    
    Cryptographic Operation:
    	Operation:	Open Key.
    	Return Code:	0x80090024

    Saturday, June 8, 2019 7:14 PM
  • Hello odoll,

    The error code 0x80090024 has the symbolic name NTE_TEMPORARY_PROFILE - it is a symptom of your problem (private keys are stored in the roaming profile) rather than a cause.

    One could try to get more information about the problem by using the ETW providers "Microsoft-Windows-User Profiles General" and "Microsoft-Windows-User Profiles Service", perhaps coupled with "Microsoft-Windows-SMBClient" and tracing across a "log in", but it is probably easier to wait and see if anyone recognizes your problem and knows a solution.

    Gary 

    Saturday, June 8, 2019 7:28 PM
  • Hi Gary, thx for you swift reply.

    I did a crosscheck on a 1809 machine (which should have done before my post ;)

    As I see those failures with the error code 0x80090024 "en mass" there as well it shouldn't be the route cause, as the logon with the roaming profile works on that machine.

    Yeah, maybe it's easier to wait and see ..  but again, thx for your help!


    • Edited by odoll Saturday, June 8, 2019 7:40 PM
    Saturday, June 8, 2019 7:38 PM
  • Hi,

    Thank you for posting here.

    According to this event id 5061(0x80090024), I found some articles below:

    https://social.technet.microsoft.com/Forums/en-US/9ade28ed-2b67-4a07-a236-9ee310bd0a92/an-internal-error-occurred-on-the-report-server-see-the-error-log-for-more-details?forum=sqlreportingservices

    https://answers.microsoft.com/en-us/windows/forum/all/event-id-5061/dd4fa0e3-ab0d-4da3-9c91-0e563f4a6400

    https://docs.microsoft.com/en-us/windows/security/threat-protection/auditing/event-5061

    Hope the information there can be helpful.

    Best Regards,

    Lavilian


    Please remember to mark the replies as answers if they help and unmark them if they provide no help.
    If you have feedback for TechNet Subscriber Support, contact tnmff@microsoft.com.

    Tuesday, June 11, 2019 9:24 AM
  • Hi,

    Just checking in to see if the information provided above was helpful. Please let us know if you would like further assistance.

    Best Regards,

    Lavilian


    Please remember to mark the replies as answers if they help and unmark them if they provide no help.
    If you have feedback for TechNet Subscriber Support, contact tnmff@microsoft.com.

    Thursday, June 13, 2019 3:46 AM
  • Hello Odoll,

    I did not expand on the idea of using ETW to analyse the problem earlier because I was not sure which of the many thousand ETW providers would be helpful and any set that I did propose would have the potential of unintentionally exposing "information" (e.g. file data in SMB traffic).

    These concerns still exist but, just in case, below is a description of the first step that I would take.

    Create a file with the following 3 lines (say with a name like "firstcut.lst"):

    "Microsoft-Windows-User Profiles General"
    "Microsoft-Windows-User Profiles Service"
    Microsoft-Windows-SMBClient

    The quotes are needed because the first two provider names include spaces.

    Then start an ETW session with a command like:

    logman start zurbel -ets -pf firstcut.lst -o zurbel.etl

    Then log off and back on again (to trigger the problem) and stop the ETW session with the command:

    logman stop zurbel -ets

    The resulting file "zurbel.etl" can be examined with Microsoft's Message Analyzer (MMA) and other tools.

    With some luck, useful information might be immediately obvious just by looking at the data in MMA. If not, and if you wish, you could make the data available via OneDrive, Google Drive etc. and I will take a look at it.

    Gary

    Thursday, June 13, 2019 3:39 PM
  • Hey!

    Thank you for your help, I have the same problem. If I logon with another user that already have the folder .profile.V6 I can logon but the profile is not synced, when I try to log with a new user same error appears. I followed your steps and here it's my log, hope you can help us. Regards. 

    https://drive.google.com/open?id=1fW3Kyo0KIpr3mbtLwtlG12-3-Fm-lwLS

    Thursday, June 13, 2019 6:41 PM
  • Hello Alvaro,

    Thanks for that - this is what I can see:

    Zooming in on the 683 byte message on line two:

    NetrLogonSamLogon is documented in [MS-NRPC]. The response of the RPC includes a NETLOGON_VALIDATION_SAM_INFO structure which contains a "ProfilePath" member:

    typedef struct _NETLOGON_VALIDATION_SAM_INFO {
    OLD_LARGE_INTEGER LogonTime;
    OLD_LARGE_INTEGER LogoffTime;
    OLD_LARGE_INTEGER KickOffTime;
    OLD_LARGE_INTEGER PasswordLastSet;
    OLD_LARGE_INTEGER PasswordCanChange;
    OLD_LARGE_INTEGER PasswordMustChange;
    RPC_UNICODE_STRING EffectiveName;
    RPC_UNICODE_STRING FullName;
    RPC_UNICODE_STRING LogonScript;
    RPC_UNICODE_STRING ProfilePath;
    RPC_UNICODE_STRING HomeDirectory;
    RPC_UNICODE_STRING HomeDirectoryDrive;
    unsigned short LogonCount;
    unsigned short BadPasswordCount;
    unsigned long UserId;
    unsigned long PrimaryGroupId;
    unsigned long GroupCount;
    [size_is(GroupCount)] PGROUP_MEMBERSHIP GroupIds;
    unsigned long UserFlags;
    USER_SESSION_KEY UserSessionKey;
    RPC_UNICODE_STRING LogonServer;
    RPC_UNICODE_STRING LogonDomainName;
    PRPC_SID LogonDomainId;
    unsigned long ExpansionRoom[10];
    } NETLOGON_VALIDATION_SAM_INFO,
    *PNETLOGON_VALIDATION_SAM_INFO;

    Since there was no SMB activity between NetrLogonSamLogon returning and the first report of a problem with the profile path, we can tentatively deduce that access via SMB to the profile is not the cause.

    The NetrLogonSamLogon RPC is encrypted, so I will check if there is anything that we can do to see more details about the contents of the response.

    Gary

    Thursday, June 13, 2019 8:27 PM
  • Hello Alvaro and odoll,

    This is the list of providers that I would like to trace as a next step (again, in the format that should be stored in a file like "firstcut.lst"):

    {63a3adbe-9717-410d-a0f5-e07e68823b4d} 0xFFFFFFFFFFFFFFFF 255 # ShellPerfTraceProvider
    {a323cdc2-81b0-48b2-80c8-b749a221478a} 0xFFFFFFFFFFFFFFFF 255 # ShellTraceHomeGroupProvider
    {eb7428f5-ab1f-4322-a4cc-1f1a9b2c5e98} 0xFFFFFFFFFFFFFFFF 255 # ShellTraceProvider
    {6b6c257f-5643-43e8-8e5a-c66343dbc650} 0xFFFFFFFFFFFFFFFF 255 # UstCommonProvider
    "Microsoft-Windows-User Profiles General"
    "Microsoft-Windows-User Profiles Service"
    Microsoft-Windows-Kernel-Process 0x10
    Microsoft-Windows-Kernel-File
    Microsoft-Windows-SMBClient

    The command to start the trace should be enhanced to specify the number of buffers for ETW (-nb) because Microsoft-Windows-Kernel-File is a high volume source of events:

    logman start zurbel -ets -pf firstcut.lst -nb 200 -o zurbel.etl

    The type of information that this produces can be seen below (for my standalone PC, so no roaming profile):

    Gary



    Friday, June 14, 2019 10:23 AM
  • Hello Gary, thank you so much again!

    Here is the file https://drive.google.com/open?id=1sdK2ffdaMNc1qAAbfN-XBdGW8gZM-hkW

    I have compressed because it was heavy, hope it helps.

    I'm going to check also that file, thank you!

    Friday, June 14, 2019 5:50 PM
  • Hello Alvaro,

    Thanks for that quick response - I appreciate it.

    There were however a few problems. Firstly, if you look at the very first entry in the file, you will see that 149,618 events were lost (because they were generated faster than they could be saved) - that is my fault for underestimating the amount of buffering that might be needed (my test with these parameters did not lose any events, but it is very machine/environment specific):

    If the client was Windows 10, one would also expect to see DbgIdRSDS entries for DLLs that were registered as WPP providers (for the GUID entries in the firstcut.lst file, such as {63a3adbe-9717-410d-a0f5-e07e68823b4d}). These entries are needed to find the PDB files that help to decode such events. I guess that your client is older than Windows 10.

    Finally, no events were logged for the WPP providers (those specified by GUID), possibly because the GUIDs were different in older versions of Windows.

    I checked the Microsoft-Windows-Kernel-File entries in case there were any entries showing attempts to access the roaming profile in situ, but the first profile references that I saw were these:

    For remote (file share files), the path would look like that below (typically the path starts with \Device\Mup\...) and are therefore easy to find, but there were no entries for the profile:

    Let me think some more about this - I had invested my hope in the WPP providers to give insight into the profile loading process. What version of Windows is used by the client PCs?

    Gary

    Friday, June 14, 2019 6:57 PM
  • Hi Gary!

    The version of the client is the following:

    Windows 10 Pro

    Version 1903

    OS version 18362.175


    Thank you again! Regards

    Saturday, June 15, 2019 9:38 AM
  • Hello Alvaro,

    I checked the WPP provider GUIDs on a Windows 8 system and they are the same as Windows 10, so perhaps events from these providers just got "swamped" and were all among the 149,618 lost events or perhaps the User Profile Service just logs fewer messages in older versions of Windows.

    One could try repeating the trace, omitting the Microsoft-Windows-Kernel-File provider (just delete it from the firstcut.lst file). The absence of the DbgIdRSDS information will be a problem when it comes to analysing the WPP events, but we need to be sure first that there are some WPP events to be analysed before worrying about that.

    Gary

    Saturday, June 15, 2019 9:40 AM
  • Hello Gary,

    Here is the file https://drive.google.com/open?id=1dKWBhCrU8ZgvCt_yz6t5yURAgywKNShJ

    Thank you!

    Saturday, June 15, 2019 10:05 AM
  • Hello Alvaro,

    Based on the results of my testing with Windows 8 (which generated DbgIdRSDS and WPP events), I guess that you must be using an even earlier version (Windows 7?). In your newest trace, there were no events from the WPP providers (those specified by GUID and which trace the Windows Profile Service (amongst other things)).

    The last trace was very similar to the first and contained no new information.

    An alternate approach might be to increase the logging level on the Samba server and check its logs to see if we can find anything related to the profile problem there. The first thing that I want to discover is what "profile path" does the Samba NetLogon service return to the Windows client.

    Gary

    Saturday, June 15, 2019 11:09 AM
  • Hi Alvaro, "good" to hear I'm not the only one having that issue, and thx to Gary for your ongoing effort to help us.

    Sry for my late reply, but I was more focusing to upgrade my NT4 style samba config to a AD setup (which however failed so far ...). Nevertheless I just tried to produce some samba logs for when I try to login with user "zurbel" (log level = 3 passdb:5 auth:5)

    The following is the failing logon to the W10 Pro 1903 machine:

      check_ntlm_password:  authentication for user [zurbel] -> [zurbel] -> [zurbel] succeeded
    [2019/06/16 09:55:53.163731,  3] ../source3/groupdb/mapping.c:830(pdb_create_builtin_alias)
      pdb_create_builtin_alias: Could not get a gid out of winbind
    [2019/06/16 09:55:53.163977,  2] ../source3/auth/token_util.c:564(finalize_local_nt_token)
      WARNING: Failed to create BUILTIN\Administrators group!  Can Winbind allocate gids?
    [2019/06/16 09:55:53.165198,  3] ../source3/groupdb/mapping.c:830(pdb_create_builtin_alias)
      pdb_create_builtin_alias: Could not get a gid out of winbind
    [2019/06/16 09:55:53.165394,  2] ../source3/auth/token_util.c:589(finalize_local_nt_token)
      WARNING: Failed to create BUILTIN\Users group! Can Winbind allocate gids?
    [2019/06/16 09:55:53.170589,  3] ../auth/ntlmssp/ntlmssp_sign.c:509(ntlmssp_sign_reset)
      NTLMSSP Sign/Seal - Initialising with flags:
    [2019/06/16 09:55:53.170762,  3] ../auth/ntlmssp/ntlmssp_util.c:69(debug_ntlmssp_flags)
      Got NTLMSSP neg_flags=0xe2088215
    [2019/06/16 09:55:53.170941,  3] ../auth/ntlmssp/ntlmssp_sign.c:509(ntlmssp_sign_reset)
      NTLMSSP Sign/Seal - Initialising with flags:
    [2019/06/16 09:55:53.171008,  3] ../auth/ntlmssp/ntlmssp_util.c:69(debug_ntlmssp_flags)
      Got NTLMSSP neg_flags=0xe2088215
    [2019/06/16 09:55:53.174411,  3] ../source3/groupdb/mapping.c:830(pdb_create_builtin_alias)
      pdb_create_builtin_alias: Could not get a gid out of winbind
    [2019/06/16 09:55:53.174696,  2] ../source3/auth/token_util.c:564(finalize_local_nt_token)
      WARNING: Failed to create BUILTIN\Administrators group!  Can Winbind allocate gids?
    [2019/06/16 09:55:53.176188,  3] ../source3/groupdb/mapping.c:830(pdb_create_builtin_alias)
      pdb_create_builtin_alias: Could not get a gid out of winbind
    [2019/06/16 09:55:53.176419,  2] ../source3/auth/token_util.c:589(finalize_local_nt_token)
      WARNING: Failed to create BUILTIN\Users group! Can Winbind allocate gids?
    [2019/06/16 09:55:53.177511,  3] ../source3/smbd/password.c:144(register_homes_share)
      Adding homes service for user 'zurbel' using home directory: '/home/zurbel'
    [2019/06/16 09:55:53.178010,  3] ../source3/param/loadparm.c:1536(lp_add_home)
      adding home's share [zurbel] for user 'zurbel' at '/mnt/ssd/homes/%u'
    [2019/06/16 09:55:53.178223,  4] ../source3/auth/pampass.c:483(smb_pam_start)
      smb_pam_start: PAM: Init user: zurbel
    [2019/06/16 09:55:53.195949,  4] ../source3/auth/pampass.c:492(smb_pam_start)
      smb_pam_start: PAM: setting rhost to: 194.174.11.112
    [2019/06/16 09:55:53.196142,  4] ../source3/auth/pampass.c:501(smb_pam_start)
      smb_pam_start: PAM: setting tty
    [2019/06/16 09:55:53.196211,  4] ../source3/auth/pampass.c:509(smb_pam_start)
      smb_pam_start: PAM: Init passed for user: zurbel
    [2019/06/16 09:55:53.196266,  4] ../source3/auth/pampass.c:646(smb_internal_pam_session)
      smb_internal_pam_session: PAM: tty set to: smb/3800746404
    [2019/06/16 09:55:53.199999,  4] ../source3/auth/pampass.c:465(smb_pam_end)
      smb_pam_end: PAM: PAM_END OK.
    [2019/06/16 09:55:53.202240,  3] ../source3/smbd/process.c:1958(process_smb)
      Transaction 3 of length 80 (0 toread)
    [2019/06/16 09:55:53.202429,  3] ../source3/smbd/process.c:1538(switch_message)
      switch message SMBtconX (pid 26761) conn 0x0
    [2019/06/16 09:55:53.203556,  3] ../source3/lib/access.c:338(allow_access)
      Allowed connection from 194.174.11.112 (194.174.11.112)
    [2019/06/16 09:55:53.203955,  3] ../source3/smbd/service.c:576(make_connection_snum)
      Connect path is '/tmp' for service [IPC$]
    [2019/06/16 09:55:53.204153,  3] ../source3/smbd/vfs.c:113(vfs_init_default)
      Initialising default vfs hooks
    [2019/06/16 09:55:53.204339,  3] ../source3/smbd/vfs.c:139(vfs_init_custom)
      Initialising custom vfs hooks from [/[Default VFS]/]
    [2019/06/16 09:55:53.204919,  3] ../source3/smbd/service.c:822(make_connection_snum)
      lat (ipv4:194.174.11.112:9215) connect to service IPC$ initially as user zurbel (uid=2041, gid=501) (pid 26761)
    [2019/06/16 09:55:53.205184,  3] ../source3/smbd/reply.c:1144(reply_tcon_and_X)
      tconX service=IPC$ 
    [2019/06/16 09:55:53.206218,  3] ../source3/smbd/process.c:1958(process_smb)
      Transaction 4 of length 102 (0 toread)
    [2019/06/16 09:55:53.206436,  3] ../source3/smbd/process.c:1538(switch_message)
      switch message SMBtrans2 (pid 26761) conn 0x1f1fee8
    [2019/06/16 09:55:53.206881,  3] ../source3/smbd/msdfs.c:1010(get_referred_path)
      get_referred_path: |zurbel| in dfs path \share\zurbel is not a dfs root.
    [2019/06/16 09:55:53.206997,  3] ../source3/smbd/error.c:82(error_packet_set)
      NT error packet at ../source3/smbd/trans2.c(9155) cmd=50 (SMBtrans2) NT_STATUS_NOT_FOUND
    [2019/06/16 09:55:53.210975,  3] ../source3/smbd/process.c:1958(process_smb)
      Transaction 5 of length 84 (0 toread)
    [2019/06/16 09:55:53.211181,  3] ../source3/smbd/process.c:1538(switch_message)
      switch message SMBtconX (pid 26761) conn 0x0
    [2019/06/16 09:55:53.211743,  3] ../source3/lib/access.c:338(allow_access)
      Allowed connection from 194.174.11.112 (194.174.11.112)
    [2019/06/16 09:55:53.212198,  3] ../source3/smbd/service.c:576(make_connection_snum)
      Connect path is '/mnt/ssd/homes/zurbel' for service [zurbel]
    [2019/06/16 09:55:53.212400,  3] ../source3/smbd/vfs.c:113(vfs_init_default)
      Initialising default vfs hooks
    [2019/06/16 09:55:53.212484,  3] ../source3/smbd/vfs.c:139(vfs_init_custom)
      Initialising custom vfs hooks from [/[Default VFS]/]
    [2019/06/16 09:55:53.213416,  2] ../source3/smbd/service.c:822(make_connection_snum)
      lat (ipv4:194.174.11.112:9215) connect to service zurbel initially as user zurbel (uid=2041, gid=501) (pid 26761)
    [2019/06/16 09:55:53.213839,  3] ../source3/smbd/reply.c:1144(reply_tcon_and_X)
      tconX service=ZURBEL 
    [2019/06/16 09:56:03.938677,  3] ../source3/smbd/process.c:1958(process_smb)
      Transaction 6 of length 39 (0 toread)
    [2019/06/16 09:56:03.938973,  3] ../source3/smbd/process.c:1538(switch_message)
      switch message SMBtdis (pid 26761) conn 0x1f1fee8
    [2019/06/16 09:56:03.939379,  3] ../source3/smbd/service.c:1098(close_cnum)
      lat (ipv4:194.174.11.112:9215) closed connection to service IPC$

    And this one is the successful logon to a W10 1809 (it already had a locally "cached" profile of user "zurbel) a few minutes later:

    [2019/06/16 10:12:14.330465,  3] ../source3/passdb/lookup_sid.c:1645(get_primary_group_sid)
      Forcing Primary Group to 'Domain Users' for zurbel
    [2019/06/16 10:12:14.334588,  3] ../source3/smbd/process.c:1958(process_smb)
      Transaction 1268 of length 140 (0 toread)
    [2019/06/16 10:12:14.334873,  3] ../source3/smbd/process.c:1538(switch_message)
      switch message SMBtrans (pid 27666) conn 0xb61d20
    [2019/06/16 10:12:14.335057,  3] ../source3/smbd/ipc.c:591(handle_trans)
      trans <\PIPE\> data=52 params=0 setup=2
    [2019/06/16 10:12:14.335195,  3] ../source3/smbd/ipc.c:542(named_pipe)
      named pipe command on <> name
    [2019/06/16 10:12:14.335304,  3] ../source3/smbd/ipc.c:506(api_fd_reply)
      Got API command 0x26 on pipe "samr" (pnum 56df)
    [2019/06/16 10:12:14.336089,  3] ../source3/rpc_server/srv_pipe.c:1455(api_rpcTNP)
      api_rpcTNP: rpc command: SAMR_OPENUSER
    [2019/06/16 10:12:14.339678,  3] ../source3/smbd/process.c:1958(process_smb)
      Transaction 1269 of length 134 (0 toread)
    [2019/06/16 10:12:14.339958,  3] ../source3/smbd/process.c:1538(switch_message)
      switch message SMBtrans (pid 27666) conn 0xb61d20
    [2019/06/16 10:12:14.340145,  3] ../source3/smbd/ipc.c:591(handle_trans)
      trans <\PIPE\> data=46 params=0 setup=2
    [2019/06/16 10:12:14.340283,  3] ../source3/smbd/ipc.c:542(named_pipe)
      named pipe command on <> name
    [2019/06/16 10:12:14.340404,  3] ../source3/smbd/ipc.c:506(api_fd_reply)
      Got API command 0x26 on pipe "samr" (pnum 56df)
    [2019/06/16 10:12:14.341203,  3] ../source3/rpc_server/srv_pipe.c:1455(api_rpcTNP)
      api_rpcTNP: rpc command: SAMR_QUERYUSERINFO
    [2019/06/16 10:12:14.347010,  3] ../source3/rpc_server/samr/srv_samr_nt.c:2941(_samr_QueryUserInfo)
      User:[zurbel]
    [2019/06/16 10:12:14.352018,  3] ../source3/smbd/process.c:1958(process_smb)
      Transaction 1270 of length 136 (0 toread)
    [2019/06/16 10:12:14.352312,  3] ../source3/smbd/process.c:1538(switch_message)
      switch message SMBtrans (pid 27666) conn 0xb61d20
    [2019/06/16 10:12:14.352498,  3] ../source3/smbd/ipc.c:591(handle_trans)
      trans <\PIPE\> data=48 params=0 setup=2
    [2019/06/16 10:12:14.352631,  3] ../source3/smbd/ipc.c:542(named_pipe)
      named pipe command on <> name
    [2019/06/16 10:12:14.352740,  3] ../source3/smbd/ipc.c:506(api_fd_reply)
      Got API command 0x26 on pipe "samr" (pnum 56df)
    [2019/06/16 10:12:14.353543,  3] ../source3/rpc_server/srv_pipe.c:1455(api_rpcTNP)
      api_rpcTNP: rpc command: SAMR_QUERYSECURITY
    [2019/06/16 10:12:14.354590,  3] ../source3/rpc_server/samr/srv_samr_nt.c:653(check_change_pw_access)
      User:[zurbel]
    [2019/06/16 10:12:14.358012,  3] ../source3/smbd/process.c:1958(process_smb)
      Transaction 1271 of length 132 (0 toread)
    [2019/06/16 10:12:14.358300,  3] ../source3/smbd/process.c:1538(switch_message)
      switch message SMBtrans (pid 27666) conn 0xb61d20
    [2019/06/16 10:12:14.358522,  3] ../source3/smbd/ipc.c:591(handle_trans)
      trans <\PIPE\> data=44 params=0 setup=2
    [2019/06/16 10:12:14.358688,  3] ../source3/smbd/ipc.c:542(named_pipe)
      named pipe command on <> name
    [2019/06/16 10:12:14.358817,  3] ../source3/smbd/ipc.c:506(api_fd_reply)
      Got API command 0x26 on pipe "samr" (pnum 56df)
    [2019/06/16 10:12:14.359704,  3] ../source3/rpc_server/srv_pipe.c:1455(api_rpcTNP)
      api_rpcTNP: rpc command: SAMR_GETGROUPSFORUSER
    [2019/06/16 10:12:14.364708,  3] ../source3/smbd/process.c:1958(process_smb)
      Transaction 1272 of length 216 (0 toread)
    [2019/06/16 10:12:14.364938,  3] ../source3/smbd/process.c:1538(switch_message)
      switch message SMBtrans (pid 27666) conn 0xb61d20
    [2019/06/16 10:12:14.365076,  3] ../source3/smbd/ipc.c:591(handle_trans)
      trans <\PIPE\> data=128 params=0 setup=2
    [2019/06/16 10:12:14.365164,  3] ../source3/smbd/ipc.c:542(named_pipe)
      named pipe command on <> name
    [2019/06/16 10:12:14.365237,  3] ../source3/smbd/ipc.c:506(api_fd_reply)
      Got API command 0x26 on pipe "samr" (pnum 56df)
    [2019/06/16 10:12:14.365805,  3] ../source3/rpc_server/srv_pipe.c:1455(api_rpcTNP)
      api_rpcTNP: rpc command: SAMR_GETALIASMEMBERSHIP
    [2019/06/16 10:12:14.369538,  3] ../source3/smbd/process.c:1958(process_smb)
      Transaction 1273 of length 132 (0 toread)
    [2019/06/16 10:12:14.369802,  3] ../source3/smbd/process.c:1538(switch_message)
      switch message SMBtrans (pid 27666) conn 0xb61d20
    [2019/06/16 10:12:14.370142,  3] ../source3/smbd/ipc.c:591(handle_trans)
      trans <\PIPE\> data=44 params=0 setup=2
    [2019/06/16 10:12:14.370254,  3] ../source3/smbd/ipc.c:542(named_pipe)
      named pipe command on <> name
    [2019/06/16 10:12:14.370472,  3] ../source3/smbd/ipc.c:506(api_fd_reply)
      Got API command 0x26 on pipe "samr" (pnum 56df)
    [2019/06/16 10:12:14.371165,  3] ../source3/rpc_server/srv_pipe.c:1455(api_rpcTNP)
      api_rpcTNP: rpc command: SAMR_CLOSE
    [2019/06/16 10:12:14.373775,  3] ../source3/smbd/process.c:1958(process_smb)
      Transaction 1274 of length 132 (0 toread)
    [2019/06/16 10:12:14.374087,  3] ../source3/smbd/process.c:1538(switch_message)
      switch message SMBtrans (pid 27666) conn 0xb61d20
    [2019/06/16 10:12:14.374242,  3] ../source3/smbd/ipc.c:591(handle_trans)
      trans <\PIPE\> data=44 params=0 setup=2
    [2019/06/16 10:12:14.374346,  3] ../source3/smbd/ipc.c:542(named_pipe)
      named pipe command on <> name
    [2019/06/16 10:12:14.374434,  3] ../source3/smbd/ipc.c:506(api_fd_reply)
      Got API command 0x26 on pipe "samr" (pnum 56df)
    [2019/06/16 10:12:14.375055,  3] ../source3/rpc_server/srv_pipe.c:1455(api_rpcTNP)
      api_rpcTNP: rpc command: SAMR_CLOSE
    [2019/06/16 10:12:14.377648,  3] ../source3/smbd/process.c:1958(process_smb)
      Transaction 1275 of length 132 (0 toread)
    [2019/06/16 10:12:14.377835,  3] ../source3/smbd/process.c:1538(switch_message)
      switch message SMBtrans (pid 27666) conn 0xb61d20
    [2019/06/16 10:12:14.378201,  3] ../source3/smbd/ipc.c:591(handle_trans)
      trans <\PIPE\> data=44 params=0 setup=2
    [2019/06/16 10:12:14.378314,  3] ../source3/smbd/ipc.c:542(named_pipe)
      named pipe command on <> name
    [2019/06/16 10:12:14.378400,  3] ../source3/smbd/ipc.c:506(api_fd_reply)
      Got API command 0x26 on pipe "samr" (pnum 56df)
    [2019/06/16 10:12:14.378993,  3] ../source3/rpc_server/srv_pipe.c:1455(api_rpcTNP)
      api_rpcTNP: rpc command: SAMR_CLOSE
    [2019/06/16 10:12:14.381855,  3] ../source3/smbd/process.c:1958(process_smb)
      Transaction 1276 of length 132 (0 toread)
    [2019/06/16 10:12:14.382134,  3] ../source3/smbd/process.c:1538(switch_message)
      switch message SMBtrans (pid 27666) conn 0xb61d20
    [2019/06/16 10:12:14.382275,  3] ../source3/smbd/ipc.c:591(handle_trans)
      trans <\PIPE\> data=44 params=0 setup=2
    [2019/06/16 10:12:14.382373,  3] ../source3/smbd/ipc.c:542(named_pipe)
      named pipe command on <> name
    [2019/06/16 10:12:14.382454,  3] ../source3/smbd/ipc.c:506(api_fd_reply)
      Got API command 0x26 on pipe "samr" (pnum 56df)
    [2019/06/16 10:12:14.383114,  3] ../source3/rpc_server/srv_pipe.c:1455(api_rpcTNP)
      api_rpcTNP: rpc command: SAMR_CLOSE
    [2019/06/16 10:12:14.386087,  3] ../source3/smbd/process.c:1958(process_smb)
      Transaction 1277 of length 45 (0 toread)
    [2019/06/16 10:12:14.386343,  3] ../source3/smbd/process.c:1538(switch_message)
      switch message SMBclose (pid 27666) conn 0xb61d20
    [2019/06/16 10:12:14.386489,  3] ../source3/smbd/reply.c:5404(reply_close)
      Close file fd=-1 fnum 22239 (numopen=1)
    [2019/06/16 10:12:19.060378,  3] ../source3/smbd/process.c:1958(process_smb)
      Transaction 1278 of length 45 (0 toread)
    [2019/06/16 10:12:19.060679,  3] ../source3/smbd/process.c:1538(switch_message)
      switch message SMBclose (pid 27666) conn 0xb60540
    [2019/06/16 10:12:19.061151,  3] ../source3/smbd/reply.c:5404(reply_close)
      Close file fd=35 fnum 30678 (numopen=2)
    [2019/06/16 10:12:19.061674,  2] ../source3/smbd/close.c:788(close_normal_file)
      zurbel closed file profile.V6/ntuser.ini (numopen=1) NT_STATUS_OK
    [2019/06/16 10:12:19.076972,  3] ../source3/smbd/process.c:1958(process_smb)
      Transaction 1279 of length 45 (0 toread)
    [2019/06/16 10:12:19.077217,  3] ../source3/smbd/process.c:1538(switch_message)
      switch message SMBclose (pid 27666) conn 0xb60540
    [2019/06/16 10:12:19.077361,  3] ../source3/smbd/reply.c:5404(reply_close)
      Close file fd=9 fnum 13787 (numopen=1)
    [2019/06/16 10:12:19.077827,  2] ../source3/smbd/close.c:788(close_normal_file)
      zurbel closed file profile.V6/NTUSER.DAT (numopen=0) NT_STATUS_OK
    [2019/06/16 10:12:24.806401,  3] ../source3/smbd/process.c:1958(process_smb)
      Transaction 1280 of length 39 (0 toread)
    [2019/06/16 10:12:24.806713,  3] ../source3/smbd/process.c:1538(switch_message)
      switch message SMBtdis (pid 27666) conn 0xb61d20
    [2019/06/16 10:12:24.807259,  3] ../source3/smbd/service.c:1098(close_cnum)
      inspi (ipv4:194.174.11.14:2751) closed connection to service IPC$
    

    Sunday, June 16, 2019 8:35 AM
  • Hello odell,

    Are the extracts the full amount of logging data available in both cases?

    The failure log entries start with "check_ntlm_password" and I would expect that also to be present in the success log entries.

    Finding a common point in the logs for success/failure and then trying to understand why the log entries diverge sounds like a promising approach, but I could not identify a common point near the start of the log entries.

    Gary

    Sunday, June 16, 2019 3:41 PM
  • IMO those are, due to the timestamps, the relevant (parts) of the log.smbd files.

    (no references to "zurbel in log.nmbd nor log.winbind nor syslog; I did a "service samba restart" before each of the logon tries; machine LAT with 1903 first and a few min later INSPI with 1809.)

    However I can try again tomorrow.


    • Edited by odoll Sunday, June 16, 2019 8:26 PM
    Sunday, June 16, 2019 8:26 PM
  • Hello odoll,

    If possible, it we be good to see a trace (as outlined earlier) of these 6 providers on your PC across a logoff/logon cycle:

    {63a3adbe-9717-410d-a0f5-e07e68823b4d} 0xFFFFFFFFFFFFFFFF 255 # ShellPerfTraceProvider
    {a323cdc2-81b0-48b2-80c8-b749a221478a} 0xFFFFFFFFFFFFFFFF 255 # ShellTraceHomeGroupProvider
    {eb7428f5-ab1f-4322-a4cc-1f1a9b2c5e98} 0xFFFFFFFFFFFFFFFF 255 # ShellTraceProvider
    {6b6c257f-5643-43e8-8e5a-c66343dbc650} 0xFFFFFFFFFFFFFFFF 255 # UstCommonProvider
    "Microsoft-Windows-User Profiles General"
    "Microsoft-Windows-User Profiles Service"

    From Alvaro's input, it looks as though the information returned (concerning the user's profile) from the logon request is not usable and results in attempts to load a roaming profile being aborted immediately - this leaves little room for the client PC's software version to play a role. Indeed Alvaro's clients seem to be Windows 7 or similar. In your case, an upgrade from Windows 10 1809 to 1903 seems to have triggered the problem.

    My instinct is that we currently need to focus on the Samba server, and evidence from an ETW trace that the returned profile information is response to a logon is unusable would strengthen this feeling (or undermine it, if the returned NetrLogonSamLogon profile could be seen to be usable).

    Gary

    Sunday, June 16, 2019 9:14 PM
  • Hello Gary, please find the 7z'ed version of the file zurbel.etl here: https://drive.google.com/file/d/10nogMnMDYt5nVPchuzXr9_u8zfQHmFc-

    Monday, June 17, 2019 3:15 PM
  • Hello odell,

    Thanks for that - unfortunately it did not contain the "hoped for" information. 15 DLLs logged a DbgIdRSDS entry to indicate that they generate events for (at least one of) the 4 WPP providers that I mentioned, but only two WPP entries were generated during the trace. 

    I need to do a bit more work to analyse the conditions under which the two WPP events were generated, but one thought is that the "0xFFFFFFFFFFFFFFFF 255" flags and level information might have been omitted from the providers in the firstcut.lst file.

    Manifest-based providers (like Microsoft-Windows-SMBClient) log all events by default and the "flags" argument is normally used to limit their output (e.g. "Microsoft-Windows-Kernel-Process 0x10" to just track process creation/termination rather than thread activity too), whereas WPP providers normally only log events when the flag associated with the event is explicitly set (therefore a flags value of 0xFFFFFFFFFFFFFFF to log everything).

    It is possible that the two WPP events that are present are (as an exception to the norm) logged without checking any flag.

    Gary

    Monday, June 17, 2019 6:52 PM
  • Hi,

    Just want to confirm the current situations.

    Please feel free to let us know if you need further assistance.

    Best Regards,

    Lavilian


    Please remember to mark the replies as answers if they help and unmark them if they provide no help.
    If you have feedback for TechNet Subscriber Support, contact tnmff@microsoft.com.

    Thursday, June 20, 2019 6:28 AM
  • Thx Lavilian. Does this mean you're saying that this behavior is classified as a bug now, and that we should be patient till there will be fix for this?
    • Edited by odoll Friday, June 21, 2019 2:29 PM
    Friday, June 21, 2019 2:29 PM
  • Hi,

     

    Sorry that there still is no progress on this issue even though I searched a lot and consulted other colleagues.

     

    If it isn't urgent, would you mind my changing this thread from question to general discussion to wait for other community members who might be of different opinions discuss this?

    If it is urgent, it is suggested to submit a case to Microsoft for more professional technical support based on the situation and complexity. 

     

    The following is a link in the case of submission:

    https://support.microsoft.com/en-us/gp/contactus81?forceorigin=esmc&Audience=Commercial&wa=wsignin1.0

     

    Best Regards,

    Lavilian


    Please remember to mark the replies as answers if they help and unmark them if they provide no help.
    If you have feedback for TechNet Subscriber Support, contact tnmff@microsoft.com.


    Friday, June 28, 2019 3:28 AM
  • If it isn't urgent, would you mind my changing this thread from question to general discussion to wait for other community members who might be of different opinions discuss this?

    Thx Lavilian, I'm happy, if you want to change this thread, however for me it's semi urgent, as I use the setup in a non-professional environment at home for my family.

    In the meantime I got the following hints from the samba list, however due vacation and a lack of time I wasn't able to follow up on those, yet.

    https://lists.samba.org/archive/samba/2019-June/223959.html

    Thursday, July 11, 2019 6:44 PM
  • add to [globa]

    reset on zero vc = yes

    and [profiles]

    oplock = no
    level2 oplock = no

    restart samba 

    let me know :)


    • Edited by rafalrk Saturday, July 27, 2019 6:38 PM
    Saturday, July 27, 2019 6:37 PM
  • Thx rafalrk,

    though my NT4-Style DC with "Single Label DNS Domain" hasn't a [profiles] section I added your suggestions as above. However a testparm gives me the following errors

    root@share:~# testparm
    Load smb config files from /etc/samba/smb.conf
    rlimit_max: increasing rlimit_max (1024) to minimum Windows limit (16384)
    Processing section "[profiles]"
    Unknown parameter encountered: "oplock"
    Ignoring unknown parameter "oplock"
    Unknown parameter encountered: "level2 oplock"
    Ignoring unknown parameter "level2 oplock"
    WARNING: No path in service profiles - making it unavailable!
    NOTE: Service profiles is flagged unavailable.
    Processing section "[homes]"
    Processing section "[netlogon]"
    Processing section "[eBook]"
    Processing section "[Music]"
    Processing section "[Pictures]"
    Processing section "[Public]"
    Processing section "[Software]"
    Loaded services file OK.
    Server role: ROLE_DOMAIN_PDC

    So I removed [profiles] section and it's settings and just left the one for [global] but that doesn't do the trick. I still get a "We can't sign in to your account" error msg.


    • Edited by odoll Sunday, July 28, 2019 12:02 PM
    • Proposed as answer by rafalrk Tuesday, July 30, 2019 8:06 AM
    Sunday, July 28, 2019 12:02 PM
  • Microsoft dropped support for NT4 style domain controllers. Windows 7 was the last version which supported it. 

    It time to enable support to AD-DC mode 

    https://wiki.samba.org/index.php/Updating_Samba


    • Edited by rafalrk Tuesday, July 30, 2019 8:09 AM
    Tuesday, July 30, 2019 8:07 AM
  • I had this problem too - 1903 not able to log in as any users whereas the same machine on 1809 was perfectly fine.
    I've just added the suggested entries into my smb.conf, though the "profiles" entries I put in "homes" instead, as that's what I use. I then reloaded samba (not restarted) and restarted my PC. I logged in again with the same error, though looking at the event viewer it was actually a different error behind the scenes.
    This time, I shut the machine down, then killed all the samba sessions for my user (I still had 1 open), restarted samba (instead of reloading) then turned the computer on and logged in successfully! I checked that it's working by creating a document on my desktop then logging off, and, sure enough, it appeared in the profile folder on my desktop.
    So, it looks like this works, at least for me!

    Edit: Having said that, I just ran testparm and it also complains about the 2 oplocks entries, implying that only the one is working!

    Edit2: Having just checked the samb documentation, I believe we are looking for:

    oplocks = false
    level2 oplocks = false

    rather than:

    oplock = no
    level2 oplock = no

    Note the extra "s". Though mine worked without adding those anyway.

    • Edited by HoG IT Friday, August 2, 2019 2:39 PM
    Friday, August 2, 2019 2:11 PM
  • Sry, just came back to your suggestion today. But though I haven't tried those yet I just installed MS'es monthly patches this morning, and it looks like those may have fixed the issue?!?

    I just logged on with test account zurbel and the error msg "We can't sign in to your account" is gone.

    I also created a test file on the desktop and that file go sync'ed back to the user's home profile on the the DC network share after I logged off.
    Wednesday, August 14, 2019 10:57 AM