Fwupd-refresh.service has finished with a failure

1

Hi all, :wave:

when I started my system today I noticed a red “failed” entry when the initial messages were running through at boot. :frowning_face:

Getting curious what that was I looked it up after the system had started. I found this message:

lnav
[...]
│Sep 23 13:10:20 rosika-10159 systemd[1]: Starting Refresh fwupd metadata and update motd...                                                                                                                                                [...]
│Sep 23 13:10:33 rosika-10159 systemd[1]: Failed to start Refresh fwupd metadata and update motd.                                                                                                                                         │

So I tried to the following:

systemctl status fwupd-refresh.service
● fwupd-refresh.service - Refresh fwupd metadata and update motd
     Loaded: loaded (/lib/systemd/system/fwupd-refresh.service; static; vendor preset: disable>
     Active: failed (Result: exit-code) since Fri 2022-09-23 13:23:32 CEST; 42min ago
TriggeredBy: ● fwupd-refresh.timer
       Docs: man:fwupdmgr(1)
    Process: 3981 ExecStart=/usr/bin/fwupdmgr refresh (code=exited, status=1/FAILURE)
   Main PID: 3981 (code=exited, status=1/FAILURE)

Sep 23 13:23:32 rosika-10159 systemd[1]: Starting Refresh fwupd metadata and update motd...
Sep 23 13:23:32 rosika-10159 systemd[1]: fwupd-refresh.service: Main process exited, code=exit>
Sep 23 13:23:32 rosika-10159 systemd[1]: fwupd-refresh.service: Failed with result 'exit-code'.
Sep 23 13:23:32 rosika-10159 systemd[1]: Failed to start Refresh fwupd metadata and update mot>

Hmm, seems something is not right there. :thinking:

Now I tried to find something regarding that matter on the internet. And indeed there seem to be numerous posts dealing with this kind of problem.
It seems I´m not alone with that…

On server - cannot start fwupd-refresh service - Ask Ubuntu I found the following hint:

systemctl daemon-reload; service fwupd-refresh restart; service fwupd-refresh status

which - alas - didn´t work for me. :frowning_face:

Job for fwupd-refresh.service failed because the control process exited with error code.
See "systemctl status fwupd-refresh.service" and "journalctl -xe" for details.
● fwupd-refresh.service - Refresh fwupd metadata and update motd
     Loaded: loaded (/lib/systemd/system/fwupd-refresh.service; static; vendor preset: disable>
     Active: failed (Result: exit-code) since Fri 2022-09-23 14:19:52 CEST; 131ms ago
TriggeredBy: ● fwupd-refresh.timer
       Docs: man:fwupdmgr(1)
    Process: 10512 ExecStart=/usr/bin/fwupdmgr refresh (code=exited, status=1/FAILURE)
   Main PID: 10512 (code=exited, status=1/FAILURE)

Sep 23 14:19:52 rosika-10159 systemd[1]: Starting Refresh fwupd metadata and update motd...
Sep 23 14:19:52 rosika-10159 systemd[1]: fwupd-refresh.service: Main process exited, code=exit>
Sep 23 14:19:52 rosika-10159 systemd[1]: fwupd-refresh.service: Failed with result 'exit-code'.
Sep 23 14:19:52 rosika-10159 systemd[1]: Failed to start Refresh fwupd metadata and update mot>

So I looked up journalctl -xe:

Sep 23 14:19:52 rosika-10159 systemd[1]: Starting Refresh fwupd metadata and update motd...
-- Subject: A start job for unit fwupd-refresh.service has begun execution
-- Defined-By: systemd
-- Support: http://www.ubuntu.com/support
-- 
-- A start job for unit fwupd-refresh.service has begun execution.
-- 
-- The job identifier is 2791.
Sep 23 14:19:52 rosika-10159 systemd[1]: fwupd-refresh.service: Main process exited, code=exited, status=1/FAILURE
-- Subject: Unit process exited
-- Defined-By: systemd
-- Support: http://www.ubuntu.com/support
-- 
-- An ExecStart= process belonging to unit fwupd-refresh.service has exited.
-- 
-- The process' exit code is 'exited' and its exit status is 1.
Sep 23 14:19:52 rosika-10159 systemd[1]: fwupd-refresh.service: Failed with result 'exit-code'.
-- Subject: Unit failed
-- Defined-By: systemd
-- Support: http://www.ubuntu.com/support
-- 
-- The unit fwupd-refresh.service has entered the 'failed' state with result 'exit-code'.
Sep 23 14:19:52 rosika-10159 polkitd(authority=local)[892]: Unregistered Authentication Agent for unix-process:10493:422690 (system bus name :1.111, object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale de_DE.UTF-8) (dis>
Sep 23 14:19:52 rosika-10159 systemd[1]: Failed to start Refresh fwupd metadata and update motd.
-- Subject: A start job for unit fwupd-refresh.service has failed
-- Defined-By: systemd
-- Support: http://www.ubuntu.com/support
-- 
-- A start job for unit fwupd-refresh.service has finished with a failure.
-- 
-- The job identifier is 2791 and the job result is failed.

I´m still at a loss here. Up till now all this hadn´t been an issue.

My last system update was on 2022-09-20 when I received the latest kernel 5.4.0-126-generic.
No idea whether this had anything to do with it. I may be wrong there. :question:

Has anybody got any idea what might be going on?

Thanks so much and many greetings
Rosika :slightly_smiling_face:

2

Could you run the following and post all the outputs?

/usr/bin/fwupdmgr refresh
echo $?

cat /lib/systemd/system/fwupd-refresh.service && echo
1 Like
3

Hi @Akito, :wave:

thanks for your help.

/usr/bin/fwupdmgr refresh
WARNING: UEFI firmware can not be updated in legacy BIOS mode
  See https://github.com/fwupd/fwupd/wiki/PluginFlag:legacy-bios for more information.
Updating lvfs
Downloading…             [***************************************]
Downloading…             [***************************************]
Downloading…             [***************************************]
Successfully downloaded new metadata: 0 local devices supported
rosika@rosika-10159 ~> echo $status
0

after that:

cat /lib/systemd/system/fwupd-refresh.service; and echo
[Unit]
Description=Refresh fwupd metadata and update motd
Documentation=man:fwupdmgr(1)
After=network.target

[Service]
Type=oneshot
CacheDirectory=fwupdmgr
StandardError=null
DynamicUser=yes
RestrictAddressFamilies=AF_NETLINK AF_UNIX AF_INET AF_INET6
SystemCallFilter=~@mount
ProtectKernelModules=yes
ProtectControlGroups=yes
RestrictRealtime=yes
SuccessExitStatus=2
ExecStart=/usr/bin/fwupdmgr refresh
4

Try setting this setting to “no”.

cp /lib/systemd/system/fwupd-refresh.service /lib/systemd/system/fwupd-refresh.service.bak
systemctl edit fwupd-refresh
systemctl daemon-reload; systemctl restart fwupd-refresh; systemctl status fwupd-refresh
1 Like
5

O.K.

But - just to be sure:
all the other entries in fwupd-refresh should remain the same, right :question:

6

For now, to try out, yes.

As you take a backup beforehand anyway, it does not matter, if you make a mistake. You can simply always revert to the backup.

1 Like
7

O.K., I did now what you suggested. Thanks so much @Akito :heart:

● fwupd-refresh.service - Refresh fwupd metadata and update motd
     Loaded: loaded (/lib/systemd/system/fwupd-refresh.service; static; vendor preset: disable>
    Drop-In: /etc/systemd/system/fwupd-refresh.service.d
             └─override.conf
     Active: inactive (dead) since Fri 2022-09-23 15:42:27 CEST; 38ms ago
TriggeredBy: ● fwupd-refresh.timer
       Docs: man:fwupdmgr(1)
             man:fwupdmgr(1)
    Process: 18679 ExecStart=/usr/bin/fwupdmgr refresh (code=exited, status=2)
    Process: 18695 ExecStart=/usr/bin/fwupdmgr refresh (code=exited, status=2)
   Main PID: 18695 (code=exited, status=2)

Sep 23 15:42:27 rosika-10159 systemd[1]: Starting Refresh fwupd metadata and update motd...
Sep 23 15:42:27 rosika-10159 systemd[18679]: Found pre-existing private CacheDirectory= direct>
Sep 23 15:42:27 rosika-10159 systemd[18679]: Apparently, service previously had DynamicUser= t>
Sep 23 15:42:27 rosika-10159 systemd[1]: fwupd-refresh.service: Succeeded.
Sep 23 15:42:27 rosika-10159 systemd[1]: Finished Refresh fwupd metadata and update motd.

Well, it looks a bit better now, I think.

Active: inactive (dead) since Fri 2022-09-23 15:42:27 CEST; 38ms ago

… this line doesn´t say “failed” anymore, but rather “inactive (dead)”.

Then:

instead of

Sep 23 14:19:52 rosika-10159 systemd[1]: fwupd-refresh.service: Failed with result 'exit-code'.

I get

Sep 23 15:42:27 rosika-10159 systemd[1]: fwupd-refresh.service: Succeeded. :+1:

But here :

Process: 18679 ExecStart=/usr/bin/fwupdmgr refresh (code=exited, status=2)
    Process: 18695 ExecStart=/usr/bin/fwupdmgr refresh (code=exited, status=2)

the contents within brackets are printed red. Don´t know what to make of that.

And: the extit status of the last command is:

echo $status
3

Hmm. is everything now as it should be :question:
I really don´t know…

But thank you so much for your help @Akito :heart:

Many greetings from Rosika :slightly_smiling_face:

8

Well, depends. “DynamicUser” is supposed to improve security. While it probably does not matter in this scenario, it’s still unknown, why it does not work, in the first place.

As you can see, exit code 2 means “success” in this case.

1 Like
9

Yes, you´re right. We don´t know that.

That whole thing is a mystery to me.
I guess fwupd stands for “firmware update” or something like that.
On my system I found:

whatis fwupdmgr
fwupdmgr (1)         - firmware update manager client utility

and the e.g the command fwupdmgr get-devices does work, even with the change applied:

 fwupdmgr get-devices
WARNING: UEFI firmware can not be updated in legacy BIOS mode
  See https://github.com/fwupd/fwupd/wiki/PluginFlag:legacy-bios for more information.
10159
│
└─WDC WD5000AAKX-08U6AA0:
      Device ID:          2e695f4d87e2727d0b22cad7ba75d31cb493e408
      Summary:            ATA drive
      Current version:    19.01H19
      Vendor:             Western Digital (ATA:0x101C, OUI:0014ee)
      GUID:               ab504240-2856-52d5-b083-582723ff6aab
                          e6a979fe-c89b-5b50-9db2-2afbd1a6cf1e
                          24ff4dbd-e7c5-5b25-9f85-f2aa36622f48
      Device Flags:       • Internal device
                          • Updatable
                          • System requires external power source
                          • Needs a reboot after installation
                          • Device is usable for the duration of the update

rosika@rosika-10159 ~> echo $status
0

So do you suggest I should leave it at that, i.e. with the change “DynamicUser=no” applied :question:

Best regards
Rosika :slightly_smiling_face:

P.S.:

funny thing though: fwupd-refresh.service still says;

 cat /lib/systemd/system/fwupd-refresh.service

[Service]
[...]
DynamicUser=yes
[...]

Shouldn´t that say “no” here, after the change :question: :thinking:

10

If the root cause is not relevant to you, then yes.

It’s a bit complicated with systemd, sometimes. Files can change, especially if you edit the “wrong” one. So, it might’ve changed already. I don’t know much about the precise way this is working.

11

Thanks @Akito for your opinion. :heart:

Uh, I wish I had the knowledge to ascertain whether the root cause should be relevant to me. :blush:

Of course I´d like to know by what the sudden changed behaviour (i.e. the error messages) was triggered off…
I looked a bit further still, and on Bug #1969976 “DynamicUser=1 doesn't get along with services that...” : Jammy (22.04) : Bugs : fwupd package : Ubuntu it says:

So within Ubuntu something probably needs to be done about fwupd-refresh.service.

One proposal is to remove DynamicUser=yes from the systemd unit, but this will mean fwupdgmr refresh runs as root. It’s relatively sandboxed by other security mechanisms, but still not ideal.

Hmm, if setting “DynamicUser” to “no” won´t cause any harm, I guess I´ll leave it at that…

Well, thanks a lot for your time and help @Akito .

Many greetings
Rosika :slightly_smiling_face:

12

I found out where the setting has changed:

The command systemctl cat fwupd-refresh helped:

systemctl cat fwupd-refresh
# /lib/systemd/system/fwupd-refresh.service
[Unit]
Description=Refresh fwupd metadata and update motd
Documentation=man:fwupdmgr(1)
After=network.target

[Service]
Type=oneshot
CacheDirectory=fwupdmgr
StandardError=null
DynamicUser=yes
RestrictAddressFamilies=AF_NETLINK AF_UNIX AF_INET AF_INET6
SystemCallFilter=~@mount
ProtectKernelModules=yes
ProtectControlGroups=yes
# /lib/systemd/system/fwupd-refresh.service
[Unit]
Description=Refresh fwupd metadata and update motd
Documentation=man:fwupdmgr(1)
After=network.target

[Service]
Type=oneshot
CacheDirectory=fwupdmgr
StandardError=null
DynamicUser=yes
RestrictAddressFamilies=AF_NETLINK AF_UNIX AF_INET AF_INET6
SystemCallFilter=~@mount
ProtectKernelModules=yes
ProtectControlGroups=yes
RestrictRealtime=yes
SuccessExitStatus=2
ExecStart=/usr/bin/fwupdmgr refresh

# /etc/systemd/system/fwupd-refresh.service.d/override.conf
[Unit]
Description=Refresh fwupd metadata and update motd
Documentation=man:fwupdmgr(1)
After=network.target

[Service]
Type=oneshot
CacheDirectory=fwupdmgr
StandardError=null
DynamicUser=no
RestrictAddressFamilies=AF_NETLINK AF_UNIX AF_INET AF_INET6
SystemCallFilter=~@mount
ProtectKernelModules=yes
ProtectControlGroups=yes
RestrictRealtime=yes
SuccessExitStatus=2
ExecStart=/usr/bin/fwupdmgr refresh

As we can see the value of the entry “DynamicUser” changed in override.conf; the other two entries still say “yes”.

1 Like
13

Hi Rosika.
Is that the only man page you can find relating to this issue?

and for my benefit… is there some document detailing what the various parts of systemd do, where their config files are, what parameters in config files mean, …
The whole thing is mystery to me. No wondef I avoid it.

Regards
Neville

1 Like
14

This is a small introduction into the topic.

I guess, if you want to acquire deeply technical knowledge regarding systemd, then you need to get into the documentation directly associated with the source code. I don’t know if someone gathered all documentation and made an understandable explanation of everything.

2 Likes
15

Hi Neville, :wave:

thanks for your reply.

No, there is also man fwupdmgr of course but that doesn´t tell much.
The command wupdmgr --help however is more verbose. Here the options for usage of the command are given.

I guess systemd.index is a pretty good source for info regarding that matter.

Regarding DynamicUser this one should be interesting: systemd.exec .

In the meantime I also placed a post in the Lubuntu forums: https://discourse.lubuntu.me/t/fwupd-refresh-service-has-finished-with-a-failure/3613 … as my system is Lubuntu after all :blush: .

User humpty suggested:

The service basically auto updates firmware on connected devices (e.g UEFI nvram devices). IMHO I don’t see why you have to monitor 24/7 for upgrades, so personally, I would just disable it

He also provided a link (Failed to start Refresh fwupd metadata and update motd. · Issue #2532 · fwupd/fwupd · GitHub ) which I haven´t had time to look into so far. I´ll do it a soon as possible.

UPDATE:

Following @Akito ´s suggestion from yesterday

things were good so far … but at the end of the day I reverted it to the state it had been before because I wanted to take a fresh look at it today. I had a gut feeling about that… :blush:

Well, I´ll be blessed. When starting my system today I didn´t get the “failed” message from yesterday in the boot messages. :astonished:
When my system was up and running I checked:

systemctl status fwupd-refresh.service
● fwupd-refresh.service - Refresh fwupd metadata and update motd
     Loaded: loaded (/lib/systemd/system/fwupd-refresh.service; static; vendor preset: disabled)
    Drop-In: /etc/systemd/system/fwupd-refresh.service.d
             └─override.conf
     Active: inactive (dead)
TriggeredBy: ● fwupd-refresh.timer
       Docs: man:fwupdmgr(1)
             man:fwupdmgr(1)

and lnav didn´t show the entries (unlike yesetrday) either: I looked for the keywords “fwupd” and “motd”. :+1:

I actually don´t know what the whole thing was about yesterday. Today it seems to be back to normal again… :thinking:

Thanks a lot to all of you. :heart:

Many greetings from Rosika :slightly_smiling_face:

2 Likes
16

Thanks @Akito for the links you provided… :heart:
I just noticed them right now… :blush:

They should be interesting to me as well.

Many greetings.
Rosika :slightly_smiling_face:

17

Thanks. No I think I need to understand its basic concepts and philosophy. It is much more than init. Sometimes I cant avoid it and I am lost.

1 Like
18

Hi Rosika,
That sounds like it was caused by something outside of your machine?
Software on its own does not recovrr like that.
and
Thank you for the links. Akito provided some too. I just feel so dumb whenever a systemd issue come up. The man pages are rather brief and disjointed. I will have a read.
Regards
Neville

1 Like
19

Hi Neville, :wave:

Well, I think your guess is as good as mine. :blush:
I´ll keep an eye on it. If the phenomenon might reoccur I know now how to get rid of the error messages.
I´ll apply @Akito ´s method then in setting DynamicUser to no in /lib/systemd/system/fwupd-refresh.service . :+1:

You´re very welcome, Neville.

Thanks again to both of you @Akito and @nevj :heart:.

Many greetings from Rosika :slightly_smiling_face:

2 Likes
20

Hi all, :wave:

just wanted to let you know user apt-ghetto from the Lubuntu forum posted an additional link as further reference to the topic discussed:
Bug #1909603 “Occasionally fwupd-refresh.service: Failed with re...” : Bugs : fwupd package : Ubuntu .

The most informative part of it may be:

As mentioned […] there has been several upstream discussions and it was concluded this is due to a CDN mirroring issue causing problems with the metadata design used in 1.3.x or earlier versions.
[…]
The reason that this started to “show up” in 1.3.x on focal is because focal also introduced a new systemd unit fwupd-refresh.service and fwupd-refresh.timer.
These will download metadata regularly and notify the user via the motd of any devices with firmware updates.

I see.
Well, the author refers to version 1.3.x; on my system (also focal) it´s version 1.7.5-3~20.04.1 .

I looked up the installation date:

bash -c 'zgrep installed /var/log/dpkg.log.[2-9].gz | grep fwupd'

[...]
/var/log/dpkg.log.6.gz:2022-03-13 16:24:37 status half-installed libfwupdplugin5:amd64 1.7.5-3~20.04.1
/var/log/dpkg.log.6.gz:2022-03-13 16:26:26 status installed libfwupd2:amd64 1.7.5-3~20.04.1
/var/log/dpkg.log.6.gz:2022-03-13 16:26:27 status installed fwupd:amd64 1.7.5-3~20.04.1

So it´s been a while…

Still I value the additional info. :blush:

Further info from the above mentioned source:

For anyone encountering this, a few workarounds:

  1. If you’re not ever intending on using fwupd on your machine, you can remove it
    sudo apt purge fwupd

  2. If your machine does support updates and you’ll just manually check for updates, mask the service to prevent it from running.
    sudo systemctl mask fwupd-refresh.service

  3. Modify the fwupd-refresh.service unit to set “1” as a valid return code. This would paper over the issues when there are CDN problems and potentially mean you’ll be a day or two behind in notification for new firmware updates.

The most “proper” solution in Ubuntu should be a backport of 1.4.x or 1.5.x to focal. Due to the requirements and previous agreements in SRU policy this will require alignment with the technical board as well as a MIR for libjcat which is in universe for focal. It’s in main for groovy and later.

Many greetings from Rosika :slightly_smiling_face:

1 Like