Bug 1575780
Summary: | Creating new user account after install fails on Rawhide (both Workstation and Atomic Workstation) | ||
---|---|---|---|
Product: | [Fedora] Fedora | Reporter: | Adam Williamson <awilliam> |
Component: | accountsservice | Assignee: | Matthias Clasen <mclasen> |
Status: | CLOSED ERRATA | QA Contact: | Fedora Extras Quality Assurance <extras-qa> |
Severity: | urgent | Docs Contact: | |
Priority: | unspecified | ||
Version: | rawhide | CC: | jstpierr, mclasen, pvrabec, robatino, rstrode, stefw, tiagomatos, tmraz |
Target Milestone: | --- | ||
Target Release: | --- | ||
Hardware: | All | ||
OS: | Linux | ||
Whiteboard: | |||
Fixed In Version: | accountsservice-0.6.48-1.fc28 accountsservice-0.6.49-1.fc28 | Doc Type: | If docs needed, set a value |
Doc Text: | Story Points: | --- | |
Clone Of: | Environment: | ||
Last Closed: | 2018-05-13 20:00:57 UTC | Type: | Bug |
Regression: | --- | Mount Type: | --- |
Documentation: | --- | CRM: | |
Verified Versions: | Category: | --- | |
oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |
Cloudforms Team: | --- | Target Upstream Version: | |
Embargoed: | |||
Bug Depends On: | |||
Bug Blocks: | 1517011 |
Description
Adam Williamson
2018-05-07 23:37:33 UTC
This appears to have broken between 20180419.n.0 and 20180423.n.0 . gnome-initial-setup did not change in that window, but both shadow-utils and accountsservice did. shadow-utils went from 4.5-9 to 4.5-10, changelog: * Fri Apr 20 2018 Tomáš Mráz <tmraz> - 2:4.5-10 - Raise limit for passwd and shadow entry length but also prevent writing longer entries (#1422497) accountsservice went from 0.6.42-9 to 0.6.46-1, so got all upstream changes between 0.6.42 and 0.6.46. Re-assigning to shadow-utils for now, we can change to accountsservice if that turns out to be the culprit. Note, the openQA tests attempt to create a user with the username 'test' and the password 'weakpassword'. Proposing as a Beta blocker, criterion "A working mechanism to create a user account must be clearly presented during installation and/or first boot of the installed system" - clearest violation is for the Workstation live image, where anaconda's user creation screen is suppressed, hence the *only* 'mechanism' to create a user account that is presented, does not work. GDBus.Error:org.freedesktop.Accounts.Error.Failed: running '/usr/sbin/useradd' failed: Child process exited with code 6 The exit code 6 means that group specified with -g or -G option does not exist. This does not relate to the patch added in the last shadow-utils build at all unless I screwed up something horribly. What is the exact useradd command called? Tentatively reassigning to accountsservice. It appears accountsservice doesn't log or in any way record the exact command, which is unfortunate :( The useradd command construction was last touched in this commit: https://cgit.freedesktop.org/accountsservice/commit/?id=93e2a856 which sure looks like a good candidate...but it doesn't seem like the Fedora build actually uses it, looking at the build logs: configure: ** Administrator group: wheel configure: ** Extra administrator groups: I suppose there *could* be some sort of bug in the path where EXTRA_ADMIN_GROUPS is not set, here - but I'm not sure, as I'm no C/autotools expert. But I wonder whether this: AC_ARG_WITH(extra-admin-groups, [AS_HELP_STRING([--with-extra-admin-groups],[Comma-separated list of extra groups that administrator users are part of])], ,with_extra_admin_groups="") AC_DEFINE_UNQUOTED([EXTRA_ADMIN_GROUPS], ["$with_extra_admin_groups"], [Define to the list of extra groups administrator users are part of]) and this: admin_groups = g_strdup (ADMIN_GROUP); if (EXTRA_ADMIN_GROUPS != NULL && EXTRA_ADMIN_GROUPS[0] != '\0') admin_groups = g_strconcat (admin_groups, ",", EXTRA_ADMIN_GROUPS, NULL); really work together when no `--with-extra-admin-groups` arg is specified - whether there might possibly be some bug which winds up in the command looking like: `useradd -G wheel, ` or so. It's only a guess, though. The other 'obvious' possibility is that the wheel group really doesn't exist at this point, but I can't imagine why that would be the case. I'll see if I can dig into this a bit more later today. So I've been poking at this all day, and my only conclusion so far is it's an extremely odd bug. My weirdest results have been from building accountsservice with this patch: diff --git a/src/daemon.c b/src/daemon.c index 9ec153a..73c21fc 100644 --- a/src/daemon.c +++ b/src/daemon.c @@ -1098,6 +1098,12 @@ daemon_create_user_authorized_cb (Daemon *daemon, return; } + sys_log (context, "test message"); + sys_log (context, "argv1: %s", argv[1]); + sys_log (context, "argv2: %s", argv[2]); + sys_log (context, "argv3: %s", argv[3]); + sys_log (context, "argv4: %s", argv[4]); + sys_log (context, "argv5: %s", argv[5]); if (!spawn_with_login_uid (context, argv, &error)) { throw_error (context, ERROR_FAILED, "running '%s' failed: %s", argv[0], error->message); return; Twice, with that patch applied, g-i-s actually *worked* - it created the user. These are the accounts-daemon logs from those boots: -- Reboot -- May 08 19:57:25 localhost.localdomain systemd[1]: Starting Accounts Service... May 08 19:57:25 localhost.localdomain accounts-daemon[705]: started daemon version 0.6.47 May 08 19:57:25 localhost.localdomain systemd[1]: Started Accounts Service. May 08 19:58:13 localhost-live accounts-daemon[705]: request by system-bus-name::1.83 [/usr/libexec/gnome-initial-setup pid:1317 uid:981]: create user 'test' May 08 19:58:13 localhost-live accounts-daemon[705]: request by system-bus-name::1.83 [/usr/libexec/gnome-initial-setup pid:1317 uid:981]: test message May 08 19:58:13 localhost-live accounts-daemon[705]: request by system-bus-name::1.83 [/usr/libexec/gnome-initial-setup pid:1317 uid:981]: argv1: -m May 08 19:58:13 localhost-live accounts-daemon[705]: request by system-bus-name::1.83 [/usr/libexec/gnome-initial-setup pid:1317 uid:981]: argv2: -c May 08 19:58:13 localhost-live accounts-daemon[705]: request by system-bus-name::1.83 [/usr/libexec/gnome-initial-setup pid:1317 uid:981]: argv3: test May 08 19:58:13 localhost-live accounts-daemon[705]: request by system-bus-name::1.83 [/usr/libexec/gnome-initial-setup pid:1317 uid:981]: argv4: -G May 08 19:58:13 localhost-live accounts-daemon[705]: request by system-bus-name::1.83 [/usr/libexec/gnome-initial-setup pid:1317 uid:981]: argv5: May 08 19:58:13 localhost-live useradd[1425]: new group: name=test, GID=1000 May 08 19:58:13 localhost-live useradd[1425]: new user: name=test, UID=1000, GID=1000, home=/home/test, shell=/bin/bash May 08 19:58:13 localhost-live accounts-daemon[705]: useradd: warning: the home directory already exists. May 08 19:58:13 localhost-live accounts-daemon[705]: Not copying any file from skel directory into it. May 08 19:58:13 localhost-live accounts-daemon[705]: Creating mailbox file: File exists May 08 19:58:13 localhost-live accounts-daemon[705]: request by system-bus-name::1.83 [/usr/libexec/gnome-initial-setup pid:1317 uid:981]: change account type of user 'test' (1000) to 1 May 08 19:58:13 localhost-live usermod[1431]: add 'test' to group 'wheel' May 08 19:58:13 localhost-live usermod[1431]: add 'test' to group 'test' May 08 19:58:13 localhost-live usermod[1431]: add 'test' to shadow group 'wheel' May 08 19:58:13 localhost-live usermod[1431]: add 'test' to shadow group 'test' May 08 19:58:14 localhost-live accounts-daemon[705]: request by system-bus-name::1.83 [/usr/libexec/gnome-initial-setup pid:1317 uid:981]: set password and hint of user 'test' (1000) May 08 19:58:14 localhost-live usermod[1436]: change user 'test' password May 08 19:58:42 localhost-live accounts-daemon[705]: g_variant_is_object_path: assertion 'string != NULL' failed May 08 19:58:42 localhost-live accounts-daemon[705]: g_variant_new_object_path: assertion 'g_variant_is_object_path (object_path)' failed May 08 19:58:42 localhost-live systemd[1]: accounts-daemon.service: Main process exited, code=dumped, status=11/SEGV May 08 19:58:42 localhost-live systemd[1]: accounts-daemon.service: Failed with result 'core-dump'. -- Reboot -- May 08 20:01:03 localhost.localdomain systemd[1]: Starting Accounts Service... May 08 20:01:04 localhost.localdomain accounts-daemon[703]: started daemon version 0.6.47 May 08 20:01:04 localhost.localdomain systemd[1]: Started Accounts Service. May 08 20:01:46 localhost-live accounts-daemon[703]: request by system-bus-name::1.83 [/usr/libexec/gnome-initial-setup pid:1325 uid:981]: create user 'test' May 08 20:01:46 localhost-live accounts-daemon[703]: request by system-bus-name::1.83 [/usr/libexec/gnome-initial-setup pid:1325 uid:981]: test message May 08 20:01:46 localhost-live accounts-daemon[703]: request by system-bus-name::1.83 [/usr/libexec/gnome-initial-setup pid:1325 uid:981]: argv1: -m May 08 20:01:46 localhost-live accounts-daemon[703]: request by system-bus-name::1.83 [/usr/libexec/gnome-initial-setup pid:1325 uid:981]: argv2: -c May 08 20:01:46 localhost-live accounts-daemon[703]: request by system-bus-name::1.83 [/usr/libexec/gnome-initial-setup pid:1325 uid:981]: argv3: test May 08 20:01:46 localhost-live accounts-daemon[703]: request by system-bus-name::1.83 [/usr/libexec/gnome-initial-setup pid:1325 uid:981]: argv4: -G May 08 20:01:46 localhost-live accounts-daemon[703]: request by system-bus-name::1.83 [/usr/libexec/gnome-initial-setup pid:1325 uid:981]: argv5: May 08 20:01:46 localhost-live useradd[1426]: new group: name=test, GID=1000 May 08 20:01:46 localhost-live useradd[1426]: new user: name=test, UID=1000, GID=1000, home=/home/test, shell=/bin/bash May 08 20:01:48 localhost-live accounts-daemon[703]: useradd: warning: the home directory already exists. May 08 20:01:48 localhost-live accounts-daemon[703]: Not copying any file from skel directory into it. May 08 20:01:48 localhost-live accounts-daemon[703]: Creating mailbox file: File exists May 08 20:01:48 localhost-live accounts-daemon[703]: request by system-bus-name::1.83 [/usr/libexec/gnome-initial-setup pid:1325 uid:981]: change account type of user 'test' (1000) to 1 May 08 20:01:48 localhost-live usermod[1432]: add 'test' to group 'wheel' May 08 20:01:48 localhost-live usermod[1432]: add 'test' to group 'test' May 08 20:01:48 localhost-live usermod[1432]: add 'test' to shadow group 'wheel' May 08 20:01:48 localhost-live usermod[1432]: add 'test' to shadow group 'test' May 08 20:01:48 localhost-live accounts-daemon[703]: request by system-bus-name::1.83 [/usr/libexec/gnome-initial-setup pid:1325 uid:981]: set password and hint of user 'test' (1000) May 08 20:01:48 localhost-live usermod[1437]: change user 'test' password May 08 20:02:50 localhost-live accounts-daemon[703]: g_variant_is_object_path: assertion 'string != NULL' failed May 08 20:02:50 localhost-live accounts-daemon[703]: g_variant_new_object_path: assertion 'g_variant_is_object_path (object_path)' failed May 08 20:02:50 localhost-live systemd[1]: accounts-daemon.service: Main process exited, code=dumped, status=11/SEGV May 08 20:02:50 localhost-live systemd[1]: accounts-daemon.service: Failed with result 'core-dump'. Three things, to me, are notable there. 1) in both cases accountsservice eventually crashes (due to https://bugzilla.redhat.com/show_bug.cgi?id=1573550 ) 2) in both cases, all of the argv log commands worked 3) in both cases, argv[5] is logged as being empty or null or something (not 'wheel', which is what I expected) On one attempt, however, with this same patch, the failure happened. The logs from that case are: May 08 20:03:46 localhost.localdomain systemd[1]: Starting Accounts Service... May 08 20:03:47 localhost.localdomain accounts-daemon[725]: started daemon version 0.6.47 May 08 20:03:47 localhost.localdomain systemd[1]: Started Accounts Service. May 08 20:04:39 localhost-live accounts-daemon[725]: request by system-bus-name::1.83 [/usr/libexec/gnome-initial-setup pid:1322 uid:981]: create user 'test' May 08 20:04:39 localhost-live accounts-daemon[725]: request by system-bus-name::1.83 [/usr/libexec/gnome-initial-setup pid:1322 uid:981]: test message May 08 20:04:39 localhost-live accounts-daemon[725]: request by system-bus-name::1.83 [/usr/libexec/gnome-initial-setup pid:1322 uid:981]: argv1: -m May 08 20:04:39 localhost-live accounts-daemon[725]: request by system-bus-name::1.83 [/usr/libexec/gnome-initial-setup pid:1322 uid:981]: argv2: -c May 08 20:04:39 localhost-live accounts-daemon[725]: request by system-bus-name::1.83 [/usr/libexec/gnome-initial-setup pid:1322 uid:981]: argv3: test May 08 20:04:39 localhost-live accounts-daemon[725]: request by system-bus-name::1.83 [/usr/libexec/gnome-initial-setup pid:1322 uid:981]: argv4: -G May 08 20:04:39 localhost-live accounts-daemon[725]: [99B blob data] May 08 20:04:39 localhost-live accounts-daemon[725]: [38B blob data] Two things are notable there: 1) The argv5 log message doesn't appear; instead we get a couple of mysterious "blob data" messages. As I've been playing with this, I've seen these "blob data" messages pop up more than once. 2) The service doesn't crash. Indeed, it looks like whenever the user creation fails, the service doesn't crash. Of course, this could just mean the #1573550 crash only occurs when a user account exists. Finally, I have an even more odd fourth attempt, where the user creation succeeded, but argv5 logging failed and we got a single "blob data" message: May 08 20:11:17 localhost.localdomain systemd[1]: Starting Accounts Service... May 08 20:11:18 localhost.localdomain accounts-daemon[715]: started daemon version 0.6.47 May 08 20:11:18 localhost.localdomain systemd[1]: Started Accounts Service. May 08 20:12:10 localhost-live accounts-daemon[715]: request by system-bus-name::1.83 [/usr/libexec/gnome-initial-setup pid:1322 uid:981]: create user 'test' May 08 20:12:10 localhost-live accounts-daemon[715]: request by system-bus-name::1.83 [/usr/libexec/gnome-initial-setup pid:1322 uid:981]: test message May 08 20:12:10 localhost-live accounts-daemon[715]: request by system-bus-name::1.83 [/usr/libexec/gnome-initial-setup pid:1322 uid:981]: argv1: -m May 08 20:12:10 localhost-live accounts-daemon[715]: request by system-bus-name::1.83 [/usr/libexec/gnome-initial-setup pid:1322 uid:981]: argv2: -c May 08 20:12:10 localhost-live accounts-daemon[715]: request by system-bus-name::1.83 [/usr/libexec/gnome-initial-setup pid:1322 uid:981]: argv3: test May 08 20:12:10 localhost-live accounts-daemon[715]: request by system-bus-name::1.83 [/usr/libexec/gnome-initial-setup pid:1322 uid:981]: argv4: -G May 08 20:12:10 localhost-live accounts-daemon[715]: [99B blob data] May 08 20:12:10 localhost-live useradd[1423]: new group: name=test, GID=1000 May 08 20:12:10 localhost-live useradd[1423]: new user: name=test, UID=1000, GID=1000, home=/home/test, shell=/bin/bash May 08 20:12:10 localhost-live accounts-daemon[715]: useradd: warning: the home directory already exists. May 08 20:12:10 localhost-live accounts-daemon[715]: Not copying any file from skel directory into it. May 08 20:12:10 localhost-live accounts-daemon[715]: Creating mailbox file: File exists May 08 20:12:10 localhost-live accounts-daemon[715]: request by system-bus-name::1.83 [/usr/libexec/gnome-initial-setup pid:1322 uid:981]: change account type of user 'test' (1000) to 1 May 08 20:12:10 localhost-live usermod[1429]: add 'test' to group 'wheel' May 08 20:12:10 localhost-live usermod[1429]: add 'test' to group 'test' May 08 20:12:10 localhost-live usermod[1429]: add 'test' to shadow group 'wheel' May 08 20:12:10 localhost-live usermod[1429]: add 'test' to shadow group 'test' May 08 20:12:10 localhost-live accounts-daemon[715]: request by system-bus-name::1.83 [/usr/libexec/gnome-initial-setup pid:1322 uid:981]: set password and hint of user 'test' (1000) May 08 20:12:10 localhost-live usermod[1434]: change user 'test' password May 08 20:12:28 localhost-live accounts-daemon[715]: g_variant_is_object_path: assertion 'string != NULL' failed May 08 20:12:28 localhost-live accounts-daemon[715]: g_variant_new_object_path: assertion 'g_variant_is_object_path (object_path)' failed May 08 20:12:28 localhost-live systemd[1]: accounts-daemon.service: Main process exited, code=dumped, status=11/SEGV May 08 20:12:28 localhost-live systemd[1]: accounts-daemon.service: Failed with result 'core-dump'. I really haven't got a clue what's going on here. It's really rather odd. Oh, note, I did make many attempts with other patches and with no patch at all, and never got *any* attempt where it worked until these three attempts with this patch that adds lots of log statements. I've no idea why adding all these log statements seems to make it more likely to work, though. so there does appear to be some bogus code there. both a premature free and a leak for the same variable in the same function which is kind of impressive. mind giving this a try? https://koji.fedoraproject.org/koji/taskinfo?taskID=26864137 interesting oholy already added a fix for this to an upstream bug: https://bugs.freedesktop.org/show_bug.cgi?id=101972 That seems to work indeed, and the patch makes sense to me (I actually even wondered whether that was the problem, but thought the autofree change would have fixed it - missed that it'd be freed in the `if` block, before the command is run...). Thanks. Can you send an official build? accountsservice-0.6.48-1.fc28 has been submitted as an update to Fedora 28. https://bodhi.fedoraproject.org/updates/FEDORA-2018-213e7536b3 accountsservice-0.6.49-1.fc28 has been submitted as an update to Fedora 28. https://bodhi.fedoraproject.org/updates/FEDORA-2018-0e8688f4f0 accountsservice-0.6.49-1.fc28 has been pushed to the Fedora 28 testing repository. If problems still persist, please make note of it in this bug report. See https://fedoraproject.org/wiki/QA:Updates_Testing for instructions on how to install test updates. You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2018-0e8688f4f0 accountsservice-0.6.49-1.fc28 has been pushed to the Fedora 28 stable repository. If problems still persist, please make note of it in this bug report. |