Bug 1575780 - Creating new user account after install fails on Rawhide (both Workstation and Atomic Workstation)
Summary: Creating new user account after install fails on Rawhide (both Workstation an...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: accountsservice
Version: rawhide
Hardware: All
OS: Linux
unspecified
urgent
Target Milestone: ---
Assignee: Matthias Clasen
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks: F29BetaBlocker
TreeView+ depends on / blocked
 
Reported: 2018-05-07 23:37 UTC by Adam Williamson
Modified: 2018-05-13 20:00 UTC (History)
8 users (show)

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:
Clone Of:
Environment:
Last Closed: 2018-05-13 20:00:57 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
FreeDesktop.org 101972 0 None None None 2018-05-10 14:25:59 UTC

Description Adam Williamson 2018-05-07 23:37:33 UTC
In current Fedora Rawhide, if you install without creating a user account, when g-i-s runs in 'user creation' mode after install it appears to run correctly but in fact does not actually create the account. When it quits, the system is left showing some sort of incomplete gnome-shell session.

This applies to both Workstation and Atomic Workstation.

journal extract:

May 07 13:58:06 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com accounts-daemon[677]: request by system-bus-name::1.80 [/usr/libexec/gnome-initial-setup pid:1287 uid:970]: create user 'test'
May 07 13:58:06 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com accounts-daemon[677]: [38B blob data]
May 07 13:58:06 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com gnome-initial-s[1287]: Failed to create user: GDBus.Error:org.freedesktop.Accounts.Error.Failed: running '/usr/sbin/useradd' failed: Child process exited with code 6
May 07 13:58:06 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com gnome-initial-s[1287]: act_user_set_password: assertion 'ACT_IS_USER (user)' failed
May 07 13:58:07 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com gnome-initial-s[1287]: act_user_get_uid: assertion 'ACT_IS_USER (user)' failed
May 07 13:58:07 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com gnome-initial-s[1287]: act_user_get_user_name: assertion 'ACT_IS_USER (user)' failed
May 07 13:58:07 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com gnome-initial-s[1287]: g_variant_new_string: assertion 'string != NULL' failed
May 07 13:58:07 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com gdm-password][1383]: AccountsService: ActUserManager: user (null) has no username (uid: -1)
May 07 13:58:07 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com gdm-password][1383]: pam_unix(gdm-password:auth): check pass; user unknown
May 07 13:58:07 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com gdm-password][1383]: pam_unix(gdm-password:auth): authentication failure; logname= uid=0 euid=0 tty=/dev/tty1 ruser= rhost=
May 07 13:58:07 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com gdm-password][1383]: gkr-pam: error looking up user information
May 07 13:58:07 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com audit[1383]: USER_AUTH pid=1383 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:xdm_t:s0-s0:c0.c1023 msg='op=PAM:authentication grantors=? acct=5B496E76616C6964205554462D385D exe="/usr/libexec/gdm-session-worker" hostname=ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com addr=? terminal=/dev/tty1 res=failed'
May 07 13:58:07 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com gnome-shell[1120]: Object Meta.WindowActor (0x562dc22a87a0), has been already finalized. Impossible to get any property from it.
May 07 13:58:07 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com gnome-shell[1120]: Object Meta.WindowActor (0x562dc22a87a0), has been already finalized. Impossible to set any property to it.
May 07 13:58:07 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com setup-shell.desktop[1120]: == Stack trace for context 0x562dc0e42050 ==
May 07 13:58:07 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com setup-shell.desktop[1120]: #0 0x562dc11cbcc0 i   resource:///org/gnome/shell/ui/tweener.js:73 (0x7fd8f76c7cd0 @ 9)
May 07 13:58:07 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com setup-shell.desktop[1120]: #1 0x562dc11cbc40 i   resource:///org/gnome/shell/ui/tweener.js:105 (0x7fd8f76c7f78 @ 36)
May 07 13:58:07 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com setup-shell.desktop[1120]: #2 0x562dc11cbbb8 i   resource:///org/gnome/shell/ui/tweener.js:92 (0x7fd8f76c7de0 @ 52)
May 07 13:58:07 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com setup-shell.desktop[1120]: #3 0x7fffd81b8550 b   resource:///org/gnome/gjs/modules/tweener/tweener.js:208 (0x7fd8f76d2918 @ 54)
May 07 13:58:07 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com setup-shell.desktop[1120]: #4 0x7fffd81b86a0 b   resource:///org/gnome/gjs/modules/tweener/tweener.js:337 (0x7fd8f76d29a0 @ 1626)
May 07 13:58:07 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com setup-shell.desktop[1120]: #5 0x7fffd81b8750 b   resource:///org/gnome/gjs/modules/tweener/tweener.js:350 (0x7fd8f76d2a28 @ 100)
May 07 13:58:07 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com setup-shell.desktop[1120]: #6 0x562dc11cbb40 i   resource:///org/gnome/gjs/modules/tweener/tweener.js:365 (0x7fd8f76d2ab0 @ 10)
May 07 13:58:07 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com setup-shell.desktop[1120]: #7 0x7fffd81b9aa0 b   resource:///org/gnome/gjs/modules/signals.js:128 (0x7fd8f76cff78 @ 386)
May 07 13:58:07 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com setup-shell.desktop[1120]: #8 0x562dc11cbab0 i   resource:///org/gnome/shell/ui/tweener.js:207 (0x7fd8f76cf5e8 @ 159)
May 07 13:58:07 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com setup-shell.desktop[1120]: #9 0x7fffd81badd0 b   resource:///org/gnome/gjs/modules/_legacy.js:82 (0x7fd8f76b5de0 @ 71)
May 07 13:58:07 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com setup-shell.desktop[1120]: #10 0x562dc11cba30 i   resource:///org/gnome/shell/ui/tweener.js:182 (0x7fd8f76cf560 @ 15)
May 07 13:58:07 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com setup-shell.desktop[1120]: == Stack trace for context 0x562dc0e42050 ==
May 07 13:58:07 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com setup-shell.desktop[1120]: #0 0x562dc11cbcc0 i   resource:///org/gnome/shell/ui/tweener.js:80 (0x7fd8f76c7cd0 @ 82)
May 07 13:58:07 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com setup-shell.desktop[1120]: #1 0x562dc11cbc40 i   resource:///org/gnome/shell/ui/tweener.js:105 (0x7fd8f76c7f78 @ 36)
May 07 13:58:07 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com setup-shell.desktop[1120]: #2 0x562dc11cbbb8 i   resource:///org/gnome/shell/ui/tweener.js:92 (0x7fd8f76c7de0 @ 52)
May 07 13:58:07 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com setup-shell.desktop[1120]: #3 0x7fffd81b8550 b   resource:///org/gnome/gjs/modules/tweener/tweener.js:208 (0x7fd8f76d2918 @ 54)
May 07 13:58:07 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com setup-shell.desktop[1120]: #4 0x7fffd81b86a0 b   resource:///org/gnome/gjs/modules/tweener/tweener.js:337 (0x7fd8f76d29a0 @ 1626)
May 07 13:58:07 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com setup-shell.desktop[1120]: #5 0x7fffd81b8750 b   resource:///org/gnome/gjs/modules/tweener/tweener.js:350 (0x7fd8f76d2a28 @ 100)
May 07 13:58:07 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com setup-shell.desktop[1120]: #6 0x562dc11cbb40 i   resource:///org/gnome/gjs/modules/tweener/tweener.js:365 (0x7fd8f76d2ab0 @ 10)
May 07 13:58:07 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com setup-shell.desktop[1120]: #7 0x7fffd81b9aa0 b   resource:///org/gnome/gjs/modules/signals.js:128 (0x7fd8f76cff78 @ 386)
May 07 13:58:07 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com setup-shell.desktop[1120]: #8 0x562dc11cbab0 i   resource:///org/gnome/shell/ui/tweener.js:207 (0x7fd8f76cf5e8 @ 159)
May 07 13:58:07 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com setup-shell.desktop[1120]: #9 0x7fffd81badd0 b   resource:///org/gnome/gjs/modules/_legacy.js:82 (0x7fd8f76b5de0 @ 71)
May 07 13:58:07 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com setup-shell.desktop[1120]: #10 0x562dc11cba30 i   resource:///org/gnome/shell/ui/tweener.js:182 (0x7fd8f76cf560 @ 15)
May 07 13:58:09 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com audit[1383]: USER_LOGIN pid=1383 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:xdm_t:s0-s0:c0.c1023 msg='acct=[Invalid UTF-8] exe="/usr/libexec/gdm-session-worker" hostname=? addr=? terminal=? res=failed'
May 07 13:58:09 ibm-p8-kvm-03-guest-02.virt.pnr.lab.eng.rdu2.redhat.com gnome-initial-s[1287]: PAM module error: Sorry, that didn’t work. Please try again.

The log shows that both shadow-utils and accountsservice may also be involved here, so CCing those maintainers too.

Comment 1 Adam Williamson 2018-05-07 23:43:05 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'.

Comment 2 Adam Williamson 2018-05-07 23:44:31 UTC
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.

Comment 3 Tomas Mraz 2018-05-08 13:09:28 UTC
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.

Comment 4 Adam Williamson 2018-05-08 16:04:33 UTC
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.

Comment 5 Adam Williamson 2018-05-09 00:22:27 UTC
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.

Comment 6 Adam Williamson 2018-05-09 00:23:14 UTC
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.

Comment 7 Ray Strode [halfline] 2018-05-09 23:43:59 UTC
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

Comment 8 Ray Strode [halfline] 2018-05-10 14:25:59 UTC
interesting oholy already added a fix for this to an upstream bug: https://bugs.freedesktop.org/show_bug.cgi?id=101972

Comment 9 Adam Williamson 2018-05-10 16:26:58 UTC
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?

Comment 10 Fedora Update System 2018-05-10 18:28:29 UTC
accountsservice-0.6.48-1.fc28 has been submitted as an update to Fedora 28. https://bodhi.fedoraproject.org/updates/FEDORA-2018-213e7536b3

Comment 11 Fedora Update System 2018-05-10 20:36:07 UTC
accountsservice-0.6.49-1.fc28 has been submitted as an update to Fedora 28. https://bodhi.fedoraproject.org/updates/FEDORA-2018-0e8688f4f0

Comment 12 Fedora Update System 2018-05-11 18:51:57 UTC
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

Comment 13 Fedora Update System 2018-05-13 20:00:57 UTC
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.


Note You need to log in before you can comment on or make changes to this bug.