Bug 1213571 - mandb.service: "find: ‘standard output’: Broken pipe", "find: write error", "status=0/SUCCESS"
Summary: mandb.service: "find: ‘standard output’: Broken pipe", "find: write error", "...
Status: RESOLVED FIXED
Alias: None
Product: openSUSE Distribution
Classification: openSUSE
Component: Basesystem (show other bugs)
Version: Leap 15.4
Hardware: Other openSUSE Leap 15.4
: P5 - None : Normal (vote)
Target Milestone: ---
Assignee: Dr. Werner Fink
QA Contact: E-mail List
URL:
Whiteboard:
Keywords:
Depends on: 1155879
Blocks:
  Show dependency treegraph
 
Reported: 2023-07-23 16:48 UTC by Martin Jacobs
Modified: 2024-01-19 12:29 UTC (History)
5 users (show)

See Also:
Found By: ---
Services Priority:
Business Priority:
Blocker: ---
Marketing QA Status: ---
IT Deployment: ---


Attachments
Output of sudo bash -x /usr/lib/man-db/do_mandb |& tee do_mandb.log (15.81 KB, text/x-log)
2023-07-24 15:49 UTC, Martin Jacobs
Details
/usr/lib/man-db/do_mandb (1.65 KB, text/plain)
2023-07-26 06:03 UTC, Dr. Werner Fink
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Martin Jacobs 2023-07-23 16:48:40 UTC
+++ This bug was initially created as a clone of Bug #1155879 +++

I noticed this problem in the journal: mandb.service seems to fail for unknown reasons, but "success" is reported:
+++ This is new output that matches exactly that of Bug #1155879 +++
# systemctl status mandb.service
○ mandb.service - Do daily mandb update
     Loaded: loaded (/usr/lib/systemd/system/mandb.service; static)
     Active: inactive (dead) since Sun 2023-07-23 07:40:05 CEST; 10h ago
TriggeredBy: ● mandb.timer
       Docs: man:mandb(8)
             man:catman(8)
    Process: 2116 ExecStart=/usr/lib/man-db/do_mandb (code=exited, status=0/SUCCESS)
   Main PID: 2116 (code=exited, status=0/SUCCESS)

From journalctl:
Jul 23 07:39:00 Schnecke2G.Jacobs.home systemd[1]: Started Do daily mandb update.
Jul 23 07:39:00 Schnecke2G.Jacobs.home systemd[1]: Starting Do daily mandb update...
Jul 23 07:40:05 Schnecke2G.Jacobs.home do_mandb[2371]: find: ‘standard output’: Datenübergabe unterbrochen (broken pipe)
Jul 23 07:40:05 Schnecke2G.Jacobs.home do_mandb[2371]: find: Schreibfehler.
Jul 23 07:40:05 Schnecke2G.Jacobs.home systemd[1]: mandb.service: Deactivated successfully.
Jul 23 07:40:05 Schnecke2G.Jacobs.home systemd[1]: Finished Do daily mandb update.

Summary is translated from German.
Comment 1 Dr. Werner Fink 2023-07-24 08:51:22 UTC
Run as root

  bash -x /usr/lib/man-db/do_mandb |& tee do_mandb.log

and attach do_mandb.log
Comment 2 Dr. Werner Fink 2023-07-24 08:54:51 UTC
Btw: Are you using bash or an other /bin/sh ... report

  realpath /bin/sh
Comment 3 Martin Jacobs 2023-07-24 15:46:11 UTC
(In reply to Dr. Werner Fink from comment #2)
> Btw: Are you using bash or an other /bin/sh ... report
> 
>   realpath /bin/sh

Simple answer first: result of realpath

/usr/bin/bash
Comment 4 Martin Jacobs 2023-07-24 15:49:11 UTC
Created attachment 868403 [details]
Output of sudo bash -x /usr/lib/man-db/do_mandb |& tee do_mandb.log

Answer to comment #1
Comment 5 Dr. Werner Fink 2023-07-25 06:33:54 UTC
(In reply to Martin Jacobs from comment #4)
> Created attachment 868403 [details]
> Output of sudo bash -x /usr/lib/man-db/do_mandb |& tee do_mandb.log
> 
> Answer to comment #1

Hmm ... no errors ... also here mandb.service works flawsless ...
please edit /usr/lib/man-db/do_mandb and change the veriy first line
by adding a space and -x to the /bin/sh ... that is

 #!/bin/sh

becomes

 #!/bin/sh -x

and then to

 systemctl start mandb.service

to see what had happen please call

 journalctl -b 0 -o with-unit --unit mandb.service > mandb.log

and attach the file mandb.log
Comment 6 Martin Jacobs 2023-07-25 20:22:11 UTC
Maybe I did forget to mention: The error seems to occur only as part of system start, while many tasks run in parallel. I did recognize this only because command apropos did not give any results.

Here are top 5 lines of output of systemd-analyze blame

1min 8.819s mandb.service
1min 8.238s mlocate.service
    26.635s clamd.service
    23.526s backup-rpmdb.service
    21.007s logrotate.service

The astonishing result is, that mandb.service is listed in top, even before mlocate.service and clamd.service!

mandb.service is NOT part of critical chain!


I guess the performance issue of mandb.service triggers timeouts on read statement (-t 1) and thus hinders mandb.service to successfully complete its job.

And running do_mandb from the command line after boot does not give more insight, as it runs fine in this state if the system.
Comment 7 Dr. Werner Fink 2023-07-26 06:03:58 UTC
Created attachment 868432 [details]
/usr/lib/man-db/do_mandb

(In reply to Martin Jacobs from comment #6)
> Maybe I did forget to mention: The error seems to occur only as part of
> system start, while many tasks run in parallel. I did recognize this only
> because command apropos did not give any results.
> 
> Here are top 5 lines of output of systemd-analyze blame
> 
> 1min 8.819s mandb.service
> 1min 8.238s mlocate.service
>     26.635s clamd.service
>     23.526s backup-rpmdb.service
>     21.007s logrotate.service
> 
> The astonishing result is, that mandb.service is listed in top, even before
> mlocate.service and clamd.service!
> 
> mandb.service is NOT part of critical chain!
> 
> 
> I guess the performance issue of mandb.service triggers timeouts on read
> statement (-t 1) and thus hinders mandb.service to successfully complete its
> job.
> 
> And running do_mandb from the command line after boot does not give more
> insight, as it runs fine in this state if the system.

Please test out the attachment as replacement of 
 /usr/lib/man-db/do_mandb
but make sure to run
 chmod a+x /usr/lib/man-db/do_mandb
Comment 8 Martin Jacobs 2023-07-27 18:48:36 UTC
And here's result of todays boot:

top 5 lines from systemd-analyze blame

1min 32.931s mlocate.service
1min 13.890s mandb.service
     30.181s clamd.service
     24.693s backup-rpmdb.service
     13.217s dev-disk-by\x2duuid-a988af6f\x2de4bd\x2d4e00\x2dab22\x2d5092449311ee.device

And result of journalctl -b 0 -o with-unit --unit mandb.service

Thu 2023-07-27 20:17:33 CEST Schnecke2G.Jacobs.home init.scope[1]: Starting Do daily mandb update...
Thu 2023-07-27 20:18:48 CEST Schnecke2G.Jacobs.home init.scope[1]: mandb.service: Deactivated successfully.
Thu 2023-07-27 20:18:48 CEST Schnecke2G.Jacobs.home init.scope[1]: Finished Do daily mandb update.

So, your patch improves behavior of do_mandb definitely!
Comment 9 Martin Jacobs 2023-07-28 05:31:40 UTC
Same result today.
:-)
Comment 10 Dr. Werner Fink 2024-01-19 12:29:59 UTC
Now systemd timer based