Re: [powerpc] Fingerprint systemd service fails to start (next-20220624)

[Kuniyuki Iwashima <kuniyu@amazon.com>]

From:   Sachin Sant <sachinp@linux.ibm.com>
Date:   Thu, 30 Jun 2022 16:07:06 +0530
>>> Yes, the problem can be recreated after login. I have collected the strace
>>> logs.
>> 
>> I confirmed fprintd failed to launch with this message on failure case.
>> 
>> ===
>> ltcden8-lp6 fprintd[2516]: (fprintd:2516): fprintd-WARNING **: 01:56:45.705: Failed to open connection to bus: Could not connect: Connection refused
>> ===
>> 
>> 
>> But in the strace log of both cases, only one socket is created and
>> following connect() completes without an error.  And the peer socket
>> does not seem to be d-bus one.
>> 
>> ===
>> $ cat working-case/strace-fprintd-service.log | grep "socket("
>> 01:52:08 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
>> $ cat working-case/strace-fprintd-service.log | grep "socket(" -A 10
>> 01:52:08 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
>> ...
>> 01:52:08 connect(3, {sa_family=AF_UNIX, sun_path="/run/systemd/private"}, 22) = 0
>> ...
>> $ cat not-working-case/strace-fprintd-service.log | grep "socket("
>> 01:58:14 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
>> $ cat not-working-case/strace-fprintd-service.log | grep "socket(" -A 10
>> 01:58:14 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
>> ...
>> 01:58:14 connect(3, {sa_family=AF_UNIX, sun_path="/run/systemd/private"}, 22) = 0
>> ===
>> 
>> So I think the error message part is not traced well.
>> Could you try to strace directly for the command in ExecStart section of
>> its unit file?
>> 
> 
> Thank you for your inputs. This is what I did, changed the ExecStart
> line in /usr/lib/systemd/system/fprintd.service to
> 
> ExecStart=strace -t -ff /usr/libexec/fprintd
> 
> Captured the logs after recreating the problem.
> fprintd-pass-strace.log (working case) and
> fprintd-strace-fail.log (failing case).
> 
> In case of failure I see following:
> 
> Jun 30 05:52:41 ltcden8-lp6 strace[5595]: [pid  5599] 05:52:41 connect(5, {sa_family=AF_UNIX, sun_path="/var/run/dbus/system_bus_socket"}, 110) = -1 ECONNREFUSED (Connection refused)
> fprintd-fail-strace.log:Jun 30 05:52:41 ltcden8-lp6 strace[5595]: [pid  5599] 05:52:41 sendmsg(5, {msg_name={sa_family=AF_UNIX, sun_path="/run/systemd/journal/socket"}, msg_namelen=29, msg_iov=[{iov_base="GLIB_OLD_LOG_API", iov_len=16}, {iov_base="=", iov_len=1}, {iov_base="1", iov_len=1}, {iov_base="\n", iov_len=1}, {iov_base="MESSAGE", iov_len=7}, {iov_base="=", iov_len=1}, {iov_base="Failed to open connection to bus"..., iov_len=71}, {iov_base="\n", iov_len=1}, {iov_base="PRIORITY", iov_len=8}, {iov_base="=", iov_len=1}, {iov_base="4", iov_len=1}, {iov_base="\n", iov_len=1}, {iov_base="GLIB_DOMAIN", iov_len=11}, {iov_base="=", iov_len=1}, {iov_base="fprintd", iov_len=7}, {iov_base="\n", iov_len=1}], msg_iovlen=16, msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = -1 ECONNREFUSED (Connection refused)
> 
> For working case connect works
> 
> fprintd-pass-strace.log:Jun 30 05:58:18 ltcden8-lp6 strace[2585]: [pid  2658] 05:58:18 connect(5, {sa_family=AF_UNIX, sun_path="/var/run/dbus/system_bus_socket"}, 110) = 0

Thank you for collecting logs!
I will take a look today.

Best regards,
Kuniyuki


> 
> 
> - Sachin