Re: [systemd-devel] --Reboot-- lines in journal

2020-05-14 Thread Simon McVittie
On Thu, 14 May 2020 at 16:12:49 +0300, Mantas Mikulėnas wrote:
> The "--Reboot--" line is simply shown every time the _BOOT_ID field changes
> between two entries -- even if it changes to a previously seen boot ID (which
> shouldn't happen normally, but *might* be caused by lack of a RTC?).

The Raspberry Pi doesn't have a real-time clock, so if the journal
is sorting log entries by their claimed timestamp rather than by the
order in which they were actually written, it's entirely possible that
different boots will get interleaved.

In a traditional syslogd-style log file where entries are written in
order, you'd see the wallclock time jump backwards at each reboot,
then jump forwards again when NTP/etc. resynchronizes.

smcv
___
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/systemd-devel


Re: [systemd-devel] --Reboot-- lines in journal

2020-05-14 Thread Lennart Poettering
On Do, 14.05.20 16:11, Dave Howorth (syst...@howorth.org.uk) wrote:

>
> I've never even heard of a _BOOT_ID before, so it seems I'll need to do
> some reading to answer my original questions. Where's a good place to
> start?

The _BOOT_ID is simply random ID associated with every boot by the
kernel. i.e. the stuff exposed by the kernel in
/proc/sys/kernel/random/boot_id.

The journal implicitly attaches the data from that file to each log
line in the _BOOT_ID field. See systemd.journal-fields(7).


Lennart

--
Lennart Poettering, Berlin
___
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/systemd-devel


Re: [systemd-devel] --Reboot-- lines in journal

2020-05-14 Thread Dave Howorth
On Thu, 14 May 2020 16:12:49 +0300
Mantas Mikulėnas  wrote:
> On Thu, May 14, 2020 at 3:55 PM Dave Howorth 
> wrote:
> 
> > What do --Reboot-- lines in the journal mean and how do they get
> > there?
> >
> > I can't find any explanation on
> > https://www.freedesktop.org/software/systemd/man/journalctl.html or
> > related pages I've tried.
> >
> > I should explain why I'm interested. On my openSUSE box, I can see
> > for example:
> >
> > # journalctl --list-boots
> > -1 3c9ab70ade084dfab277efe733e18949 Mon 2020-03-02 23:44:11 GMT—Sun
> > 2020-03-29 08:54:38 BST
> >  0 c56183ea7877444a8252dd89a32b31f3 Sun 2020-03-29 09:15:30 BST—Thu
> > 2020-05-14 13:16:49 BST
> > # journalctl | grep Reboot
> > -- Reboot --
> > #
> >
> > Which looks fairly sane with what I think I should expect. But on
> > two Raspberry pis that I have with persistent logging enabled they
> > both have a huge excess of --Reboot-- lines. For example:
> >
> > $ sudo journalctl --list-boots
> > -3 a9346655ca5d4700ab470bfd1b94d5da Thu 2019-02-14 10:11:59 GMT—Wed
> > 2020-05-13 18:31:22 BST
> > -2 c4f8ab5ec73b40818b1607b3436b90b5 Wed 2020-05-13 18:32:51 BST—Wed
> > 2020-05-13 18:46:29 BST
> > -1 0af9c854355f4a12a64dd00e6d3d98c1 Wed 2020-05-13 19:32:57 BST—Wed
> > 2020-05-13 22:33:24 BST
> >  0 fc5b35dbb3604dfbb4e2cdc99e117a75 Wed 2020-05-13 22:33:24 BST—Thu
> > 2020-05-14 12:46:07 BST
> > $ sudo journalctl | grep Reboot | wc
> >16675047   22095
> > $
> >
> > What do the apparently excess 1664 --Reboot-- messages mean?
> >  
> 
> The "--Reboot--" line is simply shown every time the _BOOT_ID field
> changes between two entries -- even if it changes to a previously
> seen boot ID (which shouldn't happen normally, but *might* be caused
> by lack of a RTC?).
> 
> Meanwhile --list-boots has a bit more complex logic for discovering
> the boots, and it also stops the search completely if it finds a boot
> ID that it has already seen.
> 
> (What do you get from, let's say, `journalctl -o json | jq -r
> "._BOOT_ID" | uniq -c`? Does it show several distinct ranges for each
> boot ID?)

Thanks for the reply. A lot of lines similar to this (from start):

  2 4449e609d5144646b1bf70028bf8f1d0
 59 bc489744282a46ffbc28fd31de4c6aa9
 62 3164d610039145b4a1f7bc964eaaa85b
450 a9346655ca5d4700ab470bfd1b94d5da
  1 4449e609d5144646b1bf70028bf8f1d0
 27 4e807f1301de45dfb4e13551ae10a287
  1 bc489744282a46ffbc28fd31de4c6aa9
  2 4e807f1301de45dfb4e13551ae10a287
  1 4449e609d5144646b1bf70028bf8f1d0
  2 4e807f1301de45dfb4e13551ae10a287

I've attached the complete list, FWIW

I've never even heard of a _BOOT_ID before, so it seems I'll need to do
some reading to answer my original questions. Where's a good place to
start?

> -- 
> Mantas Mikulėnas


boot.file
Description: Binary data
___
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/systemd-devel


Re: [systemd-devel] --Reboot-- lines in journal

2020-05-14 Thread Mantas Mikulėnas
On Thu, May 14, 2020 at 3:55 PM Dave Howorth  wrote:

> What do --Reboot-- lines in the journal mean and how do they get there?
>
> I can't find any explanation on
> https://www.freedesktop.org/software/systemd/man/journalctl.html or
> related pages I've tried.
>
> I should explain why I'm interested. On my openSUSE box, I can see for
> example:
>
> # journalctl --list-boots
> -1 3c9ab70ade084dfab277efe733e18949 Mon 2020-03-02 23:44:11 GMT—Sun
> 2020-03-29 08:54:38 BST
>  0 c56183ea7877444a8252dd89a32b31f3 Sun 2020-03-29 09:15:30 BST—Thu
> 2020-05-14 13:16:49 BST
> # journalctl | grep Reboot
> -- Reboot --
> #
>
> Which looks fairly sane with what I think I should expect. But on two
> Raspberry pis that I have with persistent logging enabled they both
> have a huge excess of --Reboot-- lines. For example:
>
> $ sudo journalctl --list-boots
> -3 a9346655ca5d4700ab470bfd1b94d5da Thu 2019-02-14 10:11:59 GMT—Wed
> 2020-05-13 18:31:22 BST
> -2 c4f8ab5ec73b40818b1607b3436b90b5 Wed 2020-05-13 18:32:51 BST—Wed
> 2020-05-13 18:46:29 BST
> -1 0af9c854355f4a12a64dd00e6d3d98c1 Wed 2020-05-13 19:32:57 BST—Wed
> 2020-05-13 22:33:24 BST
>  0 fc5b35dbb3604dfbb4e2cdc99e117a75 Wed 2020-05-13 22:33:24 BST—Thu
> 2020-05-14 12:46:07 BST
> $ sudo journalctl | grep Reboot | wc
>16675047   22095
> $
>
> What do the apparently excess 1664 --Reboot-- messages mean?
>

The "--Reboot--" line is simply shown every time the _BOOT_ID field changes
between two entries -- even if it changes to a previously seen boot ID
(which shouldn't happen normally, but *might* be caused by lack of a RTC?).

Meanwhile --list-boots has a bit more complex logic for discovering the
boots, and it also stops the search completely if it finds a boot ID that
it has already seen.

(What do you get from, let's say, `journalctl -o json | jq -r "._BOOT_ID" |
uniq -c`? Does it show several distinct ranges for each boot ID?)

-- 
Mantas Mikulėnas
___
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/systemd-devel


Re: [systemd-devel] --Reboot-- lines in journal

2020-05-14 Thread Łukasz Niemier
> What do --Reboot-- lines in the journal mean and how do they get there?

IIRC these mean that system was restarted.

--

Łukasz Niemier
luk...@niemier.pl

___
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/systemd-devel


[systemd-devel] --Reboot-- lines in journal

2020-05-14 Thread Dave Howorth
What do --Reboot-- lines in the journal mean and how do they get there?

I can't find any explanation on
https://www.freedesktop.org/software/systemd/man/journalctl.html or
related pages I've tried.

I should explain why I'm interested. On my openSUSE box, I can see for
example:

# journalctl --list-boots
-1 3c9ab70ade084dfab277efe733e18949 Mon 2020-03-02 23:44:11 GMT—Sun 2020-03-29 
08:54:38 BST
 0 c56183ea7877444a8252dd89a32b31f3 Sun 2020-03-29 09:15:30 BST—Thu 2020-05-14 
13:16:49 BST
# journalctl | grep Reboot
-- Reboot --
# 

Which looks fairly sane with what I think I should expect. But on two
Raspberry pis that I have with persistent logging enabled they both
have a huge excess of --Reboot-- lines. For example:

$ sudo journalctl --list-boots
-3 a9346655ca5d4700ab470bfd1b94d5da Thu 2019-02-14 10:11:59 GMT—Wed 2020-05-13 
18:31:22 BST
-2 c4f8ab5ec73b40818b1607b3436b90b5 Wed 2020-05-13 18:32:51 BST—Wed 2020-05-13 
18:46:29 BST
-1 0af9c854355f4a12a64dd00e6d3d98c1 Wed 2020-05-13 19:32:57 BST—Wed 2020-05-13 
22:33:24 BST
 0 fc5b35dbb3604dfbb4e2cdc99e117a75 Wed 2020-05-13 22:33:24 BST—Thu 2020-05-14 
12:46:07 BST
$ sudo journalctl | grep Reboot | wc
   16675047   22095
$

What do the apparently excess 1664 --Reboot-- messages mean?

I can post more journal content if required.
___
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/systemd-devel


Re: [systemd-devel] systemd-networkd only brings up network interfaces when systemd-udevd sleeps for 5 seconds

2020-05-14 Thread Lennart Poettering
On Do, 07.05.20 10:00, de...@gmx.de (de...@gmx.de) wrote:

> Hi there!
>
> I'm on a Yocto system with latest v241 stable systemd. The odd thing

Latest stable systemd release is actually v245.

Consider updating, there's a good chance this already works on less
old systemd.

> is, that systemd-networkd only brings up network interfaces when
> systemd-udevd sleeps for 5 seconds at boot up.
>
> If I write the two lines
>
> [Service]
> ExecStartPost=/bin/sleep 5
>
> to /etc/systemd/system/systemd-udevd.service.d/override.conf both network 
> interfaces enp2s0 and enp3s0 come up like a charm. If I omit the two lines in 
> override.conf the two interfaces stay down. I attached the two logs with 
> systemd.log_level=debug udev.log_priority=debug enabled.
>
> It's remarkable that the order of the init phase of the interfaces switches 
> in the not working case
>
> Line 6311: May 06 10:31:23 systemd-networkd[185]: enp2s0: New device has no 
> master, continuing without

It appears networkd picks up the device before it was processed by udev.

Lennart

--
Lennart Poettering, Berlin
___
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/systemd-devel


Re: [systemd-devel] Antw: [EXT] Re: Q: systemctl kill: "Invalid who argument 15862"

2020-05-14 Thread Reindl Harald


Am 06.05.20 um 11:49 schrieb Ulrich Windl:
 Reindl Harald  schrieb am 06.05.2020 um 11:24 in
> Nachricht
> <11141_1588757087_5EB2825F_11141_72_1_3a082624-966b-a922-f8b9-ef0bb69c32f0@thelo
> nge.net>:
> 
>>
>> Am 06.05.20 um 11:21 schrieb Ulrich Windl:
>>> # systemctl kill -s HUP --kill-who=15862 iotwatch@LOC1.service 
>>>
>>> Did I misinterpret the manual page, or what is the problem?
>>>
>>>--kill-who=
>>>When used with kill, choose which processes to send a signal to.
>>>Must be one of main, control or all to select whether to kill 
>> only
>>>the main process, the control process or all processes of the 
>> unit
>>
>> 15862 !== main !== control !== all
> 
> Harald,
> 
> In the part you are not quoting is: "Main PID: 15862" 

but that changes

> So what do you want to tell us? I could not even find out which programming 
> language can parse the line above.

that it accepts the words "main", "control" or "all" and not an arbitary
number

> In case you don't want to answer, please do so, but don't answer with useless 
> messages.

Must be one of main, control or all to select whether to kill is what it
is: "main", "control" or "both"
___
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/systemd-devel


Re: [systemd-devel] Q: systemctl kill: "Invalid who argument 15862"

2020-05-14 Thread Reindl Harald



Am 06.05.20 um 11:21 schrieb Ulrich Windl:
> # systemctl kill -s HUP --kill-who=15862 iotwatch@LOC1.service 
> 
> Did I misinterpret the manual page, or what is the problem?
> 
>--kill-who=
>When used with kill, choose which processes to send a signal to.
>Must be one of main, control or all to select whether to kill only
>the main process, the control process or all processes of the unit

15862 !== main !== control !== all
___
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/systemd-devel


Re: [systemd-devel] Requested transaction contradicts existing jobs: start is destructive

2020-05-14 Thread Reindl Harald



Am 30.04.20 um 13:20 schrieb Mark Bannister:
>> On Mon, 2020-04-27 at 11:40 +0100, Mark Bannister wrote:
> 
>>> One of the error messages I've been trying to explain is reported like this:
>>> 2020-04-22T00:45:47.047710-04:00 jupiter systemd[1]: Requested transaction
>>> contradicts existing jobs: Transaction for session-752473.scope/start is
>>> destructive (user-16027.slice has 'stop' job queued, but 'start' is
>>> included in transaction).

my porblem with all that scopes, sessions and slices is that the logging
is completly useless without any username or servicename and that it's
often splittet in all 3 of them
___
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/systemd-devel


Re: [systemd-devel] network-online.target time

2020-05-14 Thread Reindl Harald


Am 22.04.20 um 16:44 schrieb Peter Morrow:
> I'm trying to optimise our boot process and have started to look at
> the time it takes for the network to come up (a single interface to be
> routable) when using systemd-networkd:
> 
> So, here systemd-networkd-wait-online.service seems to run for 3.5s -
> I had initially though this is due to the RTT for DHCP but in doing a
> packet capture for DHCP this isn't the case:
> 
> Can anyone offer any suggestions for where I should look to try to
> speed things up here?

it *is* dhcp - it's that simple

10.587s network-up.service
9.116s  network-wan-dhcp.service

"network-wan-dhcp.service" in our case is simply started by
"network-up.service" which is a simple selfmade unit using ip-commands
and nothing else

there is no way to make that simpler as in my setup

[root@srv-rhsoft:~]$ systemctl status network-wan-dhcp.service
● network-wan-dhcp.service - Internet DHCP-Client
   Loaded: loaded (/etc/systemd/system/network-wan-dhcp.service; static;
vendor preset: disabled)
   Active: active (running) since Tue 2020-04-21 19:24:58 CEST; 21h ago
 Main PID: 1296 (dhclient)
Tasks: 1 (limit: 512)
   Memory: 4.6M
  CPU: 86ms
   CGroup: /system.slice/network-wan-dhcp.service
   └─1296 /usr/sbin/dhclient -4 -q --no-pid --request-options
subnet-mask,routers br-wan
___
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/systemd-devel


[systemd-devel] systemctl status cpu/memory

2020-05-14 Thread Reindl Harald

the cpu time of 672ms is wrong, memory is missing in Fedora 31 while it
was there in previous versions though it's a oneshot service

*after* stop the service the correct cpu usage of it's lifetime is logged

[root@srv-rhsoft:~]$ systemctl status guest-arrakis.service
● guest-arrakis.service - VMware-Guest Arrakis
   Loaded: loaded (/etc/systemd/system/guest-arrakis.service; disabled;
vendor preset: disabled)
   Active: active (exited) since Wed 2020-04-29 20:42:10 CEST; 16h ago
  Process: 1408 ExecStart=/usr/bin/vmrun -T ws start
/mnt/data/fileserver/vmware/arrakis/arrakis.vmx nogui (code=exited,
status=0/SUCCESS)
 Main PID: 1408 (code=exited, status=0/SUCCESS)
  CPU: 672ms

[root@srv-rhsoft:~]$ systemctl stop guest-arrakis.service
[root@srv-rhsoft:~]$ cat messages
Apr 30 13:35:28 srv-rhsoft systemd[1]: Stopping VMware-Guest Arrakis...
Apr 30 13:35:47 srv-rhsoft systemd[1]: Stopped VMware-Guest Arrakis.
Apr 30 13:35:47 srv-rhsoft systemd[1]: guest-arrakis.service: Consumed
30min 19.944s CPU time.

[root@srv-rhsoft:~]$ cat /etc/systemd/system/guest-arrakis.service
[Unit]
Description=VMware-Guest Arrakis
PartOf=vmware-guest.target
Requisite=vmware.service
After=vmware-vmnet.service network-up.service
Wants=network-up.service

[Service]
Type=oneshot
RemainAfterExit=yes
Nice=19
IOSchedulingClass=idle
User=vmware
Group=vmware
ExecStart=/usr/bin/vmrun -T ws start
'/mnt/data/fileserver/vmware/arrakis/arrakis.vmx' nogui
ExecReload=-/usr/bin/vmrun -T ws reset
'/mnt/data/fileserver/vmware/arrakis/arrakis.vmx' nogui soft
ExecStop=-/usr/bin/vmrun -T ws stop
'/mnt/data/fileserver/vmware/arrakis/arrakis.vmx' nogui soft
ExecStop=-/usr/bin/sleep 5
TimeoutSec=300
SuccessExitStatus=255

ProtectSystem=full
CapabilityBoundingSet=~CAP_AUDIT_CONTROL CAP_AUDIT_WRITE CAP_SYS_ADMIN
CAP_SYS_BOOT CAP_SYS_PTRACE
IPAddressDeny=any
IPAddressAllow=localhost

[Install]
WantedBy=vmware-guest.target
___
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/systemd-devel