Beaglebone Black, mender-client Unparsable output: incorrect line 'ext4'

I am evaluating using mender for managing beaglebone black devices already installed. I have followed documentation to install demo mender server and ran bash script file provided by demo server to add beaglebone black board.

I haven’t figured out why yet, but after a period of time the BB ‘crashes’ - I am unable to connect to it via ssh and screen shows black with just a mouse cursor (no mouse connected but it does have a LCD4 touch screen) and requires reset to startup again. I have not connected usb serial cable yet to try see if I can glean anything but have started looking at log files.

In /var/log/messages file I see error:
level=warning msg="inventory tool /usr/share/mender/inventory/mender-inventory-rootfs-type returned unparsable output: incorrect line 'ext4'" module=inventory_data

mender-inventory-rootfs-type file contains
#!/bin/sh

# Determines what the root filesystem type is.

FS_TYPE="$(grep ' / ' /proc/mounts | awk '{print $3}')"
echo rootfs_type="$FS_TYPE"

running mender-inventory-rootfs-type outputs
rootfs_type=rootfs
ext4

cat /proc/mounts returns
rootfs / rootfs rw 0 0
sysfs /sys sysfs rw,nosuid,nodev,noexec,relatime 0 0
proc /proc proc rw,nosuid,nodev,noexec,relatime 0 0
udev /dev devtmpfs rw,relatime,size=10240k,nr_inodes=63201,mode=755 0 0
devpts /dev/pts devpts rw,nosuid,noexec,relatime,gid=5,mode=620 0 0
tmpfs /run tmpfs rw,nosuid,relatime,size=101728k,mode=755 0 0
/dev/disk/by-uuid/0cde73cc-999f-4a3c-bb74-fbafce68a889 / ext4 rw,noatime,errors=remount-ro,data=ordered 0 0
tmpfs /dev/shm tmpfs rw,nosuid,nodev,relatime 0 0

Maybe script was only meant to return 1 line, but based on /proc/mounts it will return two results rootfs and ext4

I am not sure if this is issue but it is warning I can’t explain.

Output must be in the format key=value and you can have as many as you would like as long as you follow the format.

That’s what it looked like to me and I think the script didn’t expect to have grep resolve both rootfs and ext4, I assume I can simply (for testing purposes) simply return roots_type=rootfs - agreed?

Still looking for answers on what is correct rootfs to use. If I leave mender-inventory-rootfs-type as installed then my beaglebone eventually runs out of memory. If I modify mender-inventory-rootfs-type to output rootfs_type=rootfs then it doesn’t run out of memory but I haven’t done full set of tests nor remote updates yet.

The script mender-inventory-rootfs-type uses /proc/mounts which returns two root locations:
rootfs / rootfs rw 0 0, and
/dev/disk/by-uuid/0cde73cc-999f-4a3c-bb74-fbafce68a889 / ext4 rw,noatime,errors=remount-ro,data=ordered 0 0

It looks to me that /dev/disk/by-uuid/0cde73cc-999f-4a3c-bb74-fbafce68a889 is the actual root.

My question is what should the script be returning, what it is currently returning is obviously incorrect as it’s not valid syntax.

Thanks

Hi @colinbes I have used the following blog post from time to time on desktop systems to figure out the actual root dev node:

Drew

Thanks @drewmoseley I appreciate the feedback.

As for my beaglebone the supplied script returns the wrong value for rootfs I have modified mender-inventory-rootfs-type to read:

#!/bin/sh

# Determines what the root filesystem type is.

FS_TYPE="$(/bin/findmnt -n LABEL=rootfs | awk '{print $2}')"
echo rootfs_type="$FS_TYPE"

For my setup this returns rootfs_type=/dev/disk/by-uuid/0cde73cc-999f-4a3c-bb74-fbafce68a889

As this relies on findmnt application to be installed it is not a general solution as some systems may not include it - I haven’t figured out way to reliably use /proc/mounts.

mount | grep ' / ' | awk '{print $1}' may be safer way to find rootfs than /proc/mounts

This sounds odd, that it would run out of memory. Then there might be a memory leak in the mender client on erroneous script output.

@kacf @oleorhagen, maybe you can take look quick look at the relevant code, and determinate if we need to dig deeper in to this.

My question is what should the script be returning, what it is currently returning is obviously incorrect as it’s not valid syntax.

The provided scripts are reference scripts and it is hard to provide something that will work in every environment, and you can customize these to your liking. As this is only inventory data, the Mender client & server do not look at this data and there is no “correct” value and it is up to the user to define what is correct and what they want as inventory data for their devices.

If you do not care about rootfs type or it is hard to determinate, you can simply remove the mender-inventory-rootfs-type script.

I had a quick look through the code, and I find the memory leak unlikely (from just a shallow inspection), however I’m usually wrong.

I like starting with logs. @colinbes, could you provide some logs on the memory-leak execution?

Not sure I will get to it today but over next day or so I will roll back my dev environment and use ‘faulty’ script. It takes a while to fail but will be interesting to see if error repeats itself. Since changing the script it’s been running several days with no Linux out of error exceptions.

@oleorhagen, I just did some quick experimenting and thought I’d report back as there may be a clue.

Using default script

#!/bin/sh

# Determines what the root filesystem type is.

FS_TYPE="$(grep ' / ' /proc/mounts | awk '{print $3}')"
#FS_TYPE="$(/bin/findmnt -n LABEL=rootfs | awk '{print $2}')"
echo rootfs_type="$FS_TYPE"
  • Running ps aux | grep mender after waiting couple minutes:
root@DemoNG031:/var/log# ps aux | grep mender
root     13329  2.5  1.8 861492  9636 ?        Ssl  13:32   0:03 /usr/bin/mender -daemon
root     13366  0.0  0.0      0     0 ?        Z    13:32   0:00 [mender-inventor] <defunct>
root     13418  0.0  0.0      0     0 ?        Z    13:32   0:00 [mender-inventor] <defunct>
root     13470  0.0  0.0      0     0 ?        Z    13:32   0:00 [mender-inventor] <defunct>
root     13520  0.0  0.0      0     0 ?        Z    13:32   0:00 [mender-inventor] <defunct>
root     13573  0.0  0.0      0     0 ?        Z    13:32   0:00 [mender-inventor] <defunct>
root     13621  0.0  0.0      0     0 ?        Z    13:32   0:00 [mender-inventor] <defunct>
root     13673  0.0  0.0      0     0 ?        Z    13:32   0:00 [mender-inventor] <defunct>
root     13723  0.0  0.0      0     0 ?        Z    13:32   0:00 [mender-inventor] <defunct>
root     13773  0.0  0.0      0     0 ?        Z    13:32   0:00 [mender-inventor] <defunct>
root     13823  0.0  0.0      0     0 ?        Z    13:33   0:00 [mender-inventor] <defunct>
root     13874  0.0  0.0      0     0 ?        Z    13:33   0:00 [mender-inventor] <defunct>
root     13924  0.0  0.0      0     0 ?        Z    13:33   0:00 [mender-inventor] <defunct>
root     13976  0.0  0.0      0     0 ?        Z    13:33   0:00 [mender-inventor] <defunct>
root     14024  0.0  0.0      0     0 ?        Z    13:33   0:00 [mender-inventor] <defunct>
root     14074  0.0  0.0      0     0 ?        Z    13:33   0:00 [mender-inventor] <defunct>
root     14124  0.0  0.0      0     0 ?        Z    13:33   0:00 [mender-inventor] <defunct>
root     14174  0.0  0.0      0     0 ?        Z    13:33   0:00 [mender-inventor] <defunct>
root     14224  0.0  0.0      0     0 ?        Z    13:33   0:00 [mender-inventor] <defunct>
root     14274  0.0  0.0      0     0 ?        Z    13:33   0:00 [mender-inventor] <defunct>
root     14322  0.0  0.0      0     0 ?        Z    13:33   0:00 [mender-inventor] <defunct>
root     14374  0.0  0.0      0     0 ?        Z    13:33   0:00 [mender-inventor] <defunct>
root     14424  0.0  0.0      0     0 ?        Z    13:34   0:00 [mender-inventor] <defunct>
root     14474  0.0  0.0      0     0 ?        Z    13:34   0:00 [mender-inventor] <defunct>
root     14522  0.0  0.0      0     0 ?        Z    13:34   0:00 [mender-inventor] <defunct>
root     14574  0.0  0.0      0     0 ?        Z    13:34   0:00 [mender-inventor] <defunct>
root     14624  0.0  0.0      0     0 ?        Z    13:34   0:00 [mender-inventor] <defunct>
root     14672  0.0  0.0      0     0 ?        Z    13:34   0:00 [mender-inventor] <defunct>
root     14722  0.0  0.0      0     0 ?        Z    13:34   0:00 [mender-inventor] <defunct>
root     14773  0.1  0.0      0     0 ?        Z    13:34   0:00 [mender-inventor] <defunct>
root     14824  0.0  0.0      0     0 ?        Z    13:34   0:00 [mender-inventor] <defunct>
root     14846  0.0  0.1   3132   716 pts/1    S+   13:34   0:00 grep mender
  • /var/log/messages shows repeated warning message (shown last line):
Jan 21 13:34:42 DemoNG031 mender[13329]: level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]" module=mender
Jan 21 13:34:43 DemoNG031 mender[13329]: level=info msg="State transition: check-wait [Idle] -> update-check [Sync]" module=mender
Jan 21 13:34:43 DemoNG031 mender[13329]: level=info msg="State transition: update-check [Sync] -> check-wait [Idle]" module=mender
Jan 21 13:34:47 DemoNG031 mender[13329]: level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]" module=mender
Jan 21 13:34:47 DemoNG031 mender[13329]: level=warning msg="inventory tool /usr/share/mender/inventory/mender-inventory-rootfs-type returned unparsable output: incorrect line 'ext4'" module=inventory_data
...

Using modified script

#!/bin/sh

# Determines what the root filesystem type is.

#FS_TYPE="$(grep ' / ' /proc/mounts | awk '{print $3}')"
FS_TYPE="$(/bin/findmnt -n LABEL=rootfs | awk '{print $2}')"
echo rootfs_type="$FS_TYPE"
  • Running ps aux | grep mender several times:
root@DemoNG031:/var/log# ps aux | grep mender
root     15064  0.0  0.1   3128   708 pts/1    S+   13:35   0:00 grep mender
root@DemoNG031:/var/log# ps aux | grep mender
root     15165  3.2  1.8 869684  9456 ?        Ssl  13:35   0:02 /usr/bin/mender -daemon
root     16017  0.0  0.1   3128   708 pts/1    S+   13:36   0:00 grep mender
root@DemoNG031:/var/log# ps aux | grep mender
root     15165  2.2  1.9 869684  9780 ?        Ssl  13:35   0:05 /usr/bin/mender -daemon
root     17732  0.0  0.1   3128   708 pts/1    S+   13:39   0:00 grep mender
root@DemoNG031:/var/log# ps aux | grep mender
root     15165  2.1  1.9 869684  9792 ?        Ssl  13:35   0:06 /usr/bin/mender -daemon
root     18327  0.0  0.1   3128   708 pts/1    S+   13:40   0:00 grep mender
root@DemoNG031:/var/log# ps aux | grep mender
root     15165  2.1  1.9 869684  9812 ?        Ssl  13:35   0:07 /usr/bin/mender -daemon
root     18647  0.0  0.1   3128   708 pts/1    S+   13:41   0:00 grep mender
  • /var/log/messages shows no such warning:
Jan 21 13:39:52 DemoNG031 mender[15165]: level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]" module=mender
Jan 21 13:39:53 DemoNG031 mender[15165]: level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]" module=mender
Jan 21 13:39:53 DemoNG031 mender[15165]: level=info msg="State transition: check-wait [Idle] -> update-check [Sync]" module=mender
Jan 21 13:39:53 DemoNG031 mender[15165]: level=info msg="State transition: update-check [Sync] -> check-wait [Idle]" module=mender
...

When running default script returning parsing error I see many defunct processes which I assume while (maybe) killed may still have child processes running.

Using working script I don’t see this behavior.

Obviously two very different results, hope this helps. In the meantime I have it running with ‘faulty’ script and will report when it runs out of memory which may take a while.

Thank you so much @colinbes, this very helpful. I will have a look at this first thing in the morning :smile_cat:

My pleasure. Happy to help with any testing etc.

I am trying to reduce log output for further tests and have modified /etc/systemd/system/multi-user.target.wants/mender.service in order to set log level. Service entry was changed to:

[Service]
Type=idle
User=root
Group=root
ExecStart=/usr/bin/mender -daemon -log-level warning
Restart=on-abort

But on startup and running status it still shows info level - am I missing something?

root@DemoNG031:/var/log# sudo systemctl status mender.service
mender.service - Mender OTA update service
	  Loaded: loaded (/lib/systemd/system/mender.service; enabled)
	  Active: active (running) since Tue, 21 Jan 2020 22:41:33 +0000; 4s ago
	Main PID: 16909 (mender)
	  CGroup: name=systemd:/system/mender.service
		  └ 16909 /usr/bin/mender -daemon -log-level warning

Jan 21 22:41:35 DemoNG031 mender[16909]: level=info msg="State transition: init [none] -> init [none]" module=mender
Jan 21 22:41:35 DemoNG031 mender[16909]: level=info msg="State transition: init [none] -> idle [Idle]" module=mender
Jan 21 22:41:35 DemoNG031 mender[16909]: level=info msg="authorization data present and valid" module=mender
Jan 21 22:41:35 DemoNG031 mender[16909]: level=info msg="State transition: idle [Idle] -> check-wait [Idle]" module=mender
Jan 21 22:41:35 DemoNG031 mender[16909]: level=info msg="State transition: check-wait [Idle] -> inventory-update [Sync]" module=mender
Jan 21 22:41:35 DemoNG031 mender[16909]: level=warning msg="inventory tool /usr/share/mender/inventory/mender-inventory-rootfs-type returned unpars...tory_data
Jan 21 22:41:35 DemoNG031 mender[16909]: time="2020-01-21T22:41:35Z" level=warning msg="inventory tool /usr/share/mender/inventory/mender-inventory...tory_data
Jan 21 22:41:35 DemoNG031 mender[16909]: level=info msg="State transition: inventory-update [Sync] -> check-wait [Idle]" module=mender
Jan 21 22:41:35 DemoNG031 mender[16909]: level=info msg="State transition: check-wait [Idle] -> update-check [Sync]" module=mender
Jan 21 22:41:35 DemoNG031 mender[16909]: level=info msg="State transition: update-check [Sync] -> check-wait [Idle]" module=mender

@colinbes which version of the client are you on?

@colinbes confirmed that the original issue exists. Ticket: https://tracker.mender.io/browse/MEN-3064 created if you would like to follow.

callin@DemoNG031:~$ /usr/bin/mender --version

2.1.2

runtime: go1.11.5

systemd file I modified is /etc/systemd/system/multi-user.target.wants/mender.service

Alright, so there is a slight misunderstanding here (it took me a while to comprehend this actually, as I missed the warning logged in your output). I see now that you only want to see the warning messages. In general, this is not how logging is done. It stacks. Meaning that adding a ‘deeper’ level of logging, means that all the other ‘higher’ level messages will still show up, as well as errors messages etc. So in this case, adding warning will log info and warning. Which is actually the expected behaviour.

Hence, the logs should be filtered from your system log instead :slight_smile:

I want warning and higher (error) to show in logs (or other way to put it, not include debug and info), which is pretty much how log4j etc all work so I am a little confused.

Surely setting level to info will warn on info, warning and error and exclude debug? My head boggles at it being the other way round.

In my code using log4j and similar libraries, in my code I call log.info, log.warning all depending on severity of error (message). In settings, I set log level to debug to display debug and above (i.e., all messages) or to warning to display warning and error messages only.

It is what it is, but I want to make sure we are on same page.

lol, yeah. Ur right. It is the other way around, got a bit mixed up with up and down, and down and up. sry.

Still, the filtering of ur logs should be done wherever ur logs are handled.

So, if I understand correctly, I can see nothing wrong with the client in this regard?

To me it doesn’t appear to be adhering to log-level as the document states it should.

I don’t get comment “wherever your logs are handled”. The client inserts into linux log files system, messages and daemon and while I haven’t checked I don’t see how I can go through system and message log files filtering our info messages without a lot of work - I know I can set console level filtering but that is a little different and I don’t think it can be used to filter client log levels.