systemd dependencies and processing /etc/fstab

The problem I wanted to solve

On an embedded arm system running LUbuntu 16.04 LTS (systemd 229), I wanted to add a mount point to the /etc/fstab file, which originally was like this:

# UNCONFIGURED FSTAB FOR BASE SYSTEM

Empty, except for this message. Is that a bad omen or what? This is the time to mention that the system was set up with debootstrap.

So I added this row to /etc/fstab:

#/dev/mmcblk0p1 /mnt/tfcard vfat defaults 0 0

The result: Boot failed, and systemd asked me for the root password for the sake of getting a rescue shell (the overall systemd status was “maintenance”, cutely enough).

Journalctl was kind enough to offer some not-so-helpful hints:

systemd[1]: dev-mmcblk0p1.device: Job dev-mmcblk0p1.device/start timed out.
systemd[1]: Timed out waiting for device dev-mmcblk0p1.device.
systemd[1]: Dependency failed for /mnt/tfcard.
systemd[1]: Dependency failed for Local File Systems.
systemd[1]: local-fs.target: Job local-fs.target/start failed with result 'dependency'.
systemd[1]: local-fs.target: Triggering OnFailure= dependencies.
systemd[1]: mnt-tfcard.mount: Job mnt-tfcard.mount/start failed with result 'dependency'.
systemd[1]: dev-mmcblk0p1.device: Job dev-mmcblk0p1.device/start failed with result 'timeout'.

Changing the “defaults” option to “nofail” got the system up and running, but without the required mount. That said, running “mount -a” did successfully mount the requested partition.

Spoiler: I didn’t really find a way to solve this, but I offer a fairly digestible workaround at the end of this post.

This is nevertheless an opportunity to discuss systemd dependencies and how systemd relates with /etc/fstab.

The main takeaway: Use “nofail”

This is only slightly related to the main topic, but nevertheless the most important conclusion: Open your /etc/fstab, and add “nofail” as an option to all mount points, except those that really are crucial for booting the system. That includes “/home” if it’s on a separate file system, as well as those huge file systems for storing a lot of large files. The rationale is simple: If any of these file systems are corrupt during boot, you really don’t want to be stuck on that basic textual screen (possibly with very small fonts), not having an idea what happened, and fsck asking you if you want to fix this and that. It’s much easier to figure out the problem when the failing mount points simply don’t mount, and take it from there. Not to mention that it’s much less stressful when the system is up and running. Even if not fully so.

Citing “man systemd.mount”: “With nofail, this mount will be only wanted, not required, by local-fs.target or remote-fs.target. This means that the boot will continue even if this mount point is not mounted successfully”.

To do this properly, make a tarball of /run/systemd/generator. Keep an eye on what’s in local-fs.target.requires/ vs. local-fs.target.wants/ in this directory. Only the absolutely necessary mounts should be in local-fs.target.requires/. In my system there’s only one symlink for “-.mount”, which is the root filesystem. That’s it.

Regardless, it’s a good idea that the root filesystem has the errors=remount-ro option, so if it’s mountable albeit with errors, the system still goes up.

This brief discussion will be clearer after reading through this post. Also see “nofail and dependencies” below for an elaboration on how systemd treats the “nofail” option.

/etc/fstab and systemd

At an early stage of the boot process, systemd-fstab-generator reads through /etc/fstab, and generates *.mount systemd units in /run/systemd/generator/. Inside this directory, it also generates and populates a local-fs.target.requires/ directory as well local-fs.target.wants/ in order to reflect the necessity of these units for the boot process (more about dependencies below).

So for example, in response to this row in /etc/fstab,

/dev/mmcblk0p1 /mnt/tfcard vfat nofail 0 0

the automatically generated file can be found as /run/systemd/generator/mnt-tfcard.mount as follows:

# Automatically generated by systemd-fstab-generator

[Unit]
SourcePath=/etc/fstab
Documentation=man:fstab(5) man:systemd-fstab-generator(8)

[Mount]
What=/dev/mmcblk0p1
Where=/mnt/tfcard
Type=vfat
Options=nofail

Note that the file name of a mount unit must match the mount point (as it does in this case). This is only relevant when writing mount units manually, of course.

Which brings me to my first attempt to solve the problem: Namely, to copy the automatically generated file into /etc/systemd/system/, and enable it as if I wrote it myself. And then remove the row in /etc/fstab.

More precisely, I created this file as /etc/systemd/system/mnt-tfcard.mount:

[Unit]
Description=Mount /dev/mmcblk0p1 as /mnt/tfcard

[Mount]
What=/dev/mmcblk0p1
Where=/mnt/tfcard
Type=vfat
Options=nofail

[Install]
WantedBy=multi-user.target

Note that the WantedBy is necessary for enabling the unit. multi-user.target is a bit inaccurate for this purpose, but it failed for a different reason anyhow, so who cares. It should have been “WantedBy=local-fs.target”, I believe.

Anyhow, I then went:

# systemctl daemon-reload
# systemctl enable mnt-tfcard.mount
Created symlink from /etc/systemd/system/multi-user.target.wants/mnt-tfcard.mount to /etc/systemd/system/mnt-tfcard.mount.

And then ran

# systemctl start mnt-tfcard.mount

but that was just stuck for a few seconds, and then an error message. There was no problem booting (because of “nofail”), but the mount wasn’t performed.

To investigate further, I attached strace to the systemd process (PID 1) while running the “systemctl start” command, and there was no fork. In other words, I had already then a good reason to suspect that the problem wasn’t a failed mount attempt, but that systemd didn’t go as far as trying. Which isn’t so surprising, given that the original complaint was a dependency problem.

Also, the command

# systemctl start dev-mmcblk0p1.device

didn’t finish. Checking with “systemctl”, it just said:

UNIT                 LOAD   ACTIVE     SUB       JOB   DESCRIPTION
dev-mmcblk0p1.device loaded inactive   dead      start dev-mmcblk0p1.device

[ ... ]

So have we just learned? That it’s possible to create .mount units instead of populating /etc/fstab. And that the result is exactly the same. Why that would be useful, I don’t know.

See “man systemd-fstab-generator” about how the content of fstab is translated automatically to systemd units. Also see “man systemd-fsck@.service” regarding the service that runs fsck, and refer to “man systemd.mount” regarding mount units.

A quick recap on systemd dependencies

It’s important to make a distinction between dependencies that express requirements and dependencies that express the order of launching units (“temporal dependencies”).

I’ll start with the first sort: Those that express that if one unit is activated, other units need to be activated too (“pulled in” as it’s often referred to). Note that the requirement kind of dependencies don’t say anything about one unit waiting for another to complete its activation or anything of that sort. The whole point is to start a lot of units in parallel.

So first, we have Requires=. When it appears in a unit file, it means that the listed unit must be started if the current unit is started, and that if that listed unit fails, the current unit will fail as well.

In the opposite direction, there’s RequiredBy=. It’s exactly like putting a Required= directive in the unit that is listed.

Then we have another famous couple, Wants= and its opposite WantedBy=. These are the merciful counterparts of Requires= and RequriedBy=. The difference: If the listed unit fails, the other unit may activate successfully nevertheless. The failure is marked by the fact that “systemctl status” will declare the system as “degraded”.

So the fact that basically every service unit ends with “WantedBy=multi-user.target” means that the unit file says “if multi-user.target is a requested target (i.e. practically always), you need to activate me”, but at the same time it says “if I fail, don’t fail the entire boot process”. In other words, had RequriedBy= been used all over the place instead, it would have worked just the same, as long as all units started successfully. But if one of them didn’t, one would get a textual rescue shell instead of an almost fully functional (“degraded”) system.

There are a whole lot of other directives for defining dependencies. In particular, there are also Requisite=, ConsistsOf=, BindsTo=, PartOf=, Conflicts=, plus tons of possible directives for fine-tuning the behavior of the unit, including conditions for starting and whatnot. See “man systemd.unit”. There’s also a nice summary table on that man page.

It’s important to note that even if unit X requires unit Y by virtue of the directives mentioned above, systemd may (and often will) activate them at the same time. That’s true for both “require” and “want” kind of directives. In order to control the order of activation, we have After= and Before=. After= and Before= also ensure that the stopping of units occur in the reverse order.

After= and Before= only define when the units are started, and are often used in conjunction with the directives that define requirements. But by themselves, After= and Before= don’t define a relation of requirement between units.

It’s therefore common to use Required= and After= on the same listed unit, meaning that the listed unit must complete successfully before activating the unit for which these directives are given. Same with RequiredBy= and Before=, meaning that this unit must complete before the listed unit can start.

Once again, there are more commands, and more to say on those I just mentioned. See “man systemd.unit” for detailed info on this. Really, do. It’s a good man page. There’s a lot of “but if” to be aware of.

“nofail” and dependencies

One somewhat scary side-effect of adding “nofail” is that the line saying “Before=local-fs.target” doesn’t appear in the  *.mount unit files that are automatically generated. Does it mean that the services might be started before these mounts have taken place?

I can’t say I’m 100% sure about this, but it would be really poor design if it was that way, as it would have have added a very unexpected side-effect to “nofail”. Looking at the system log of a boot with almost all mounts with “nofail”, it’s evident that they were mounted after “Reached target Local File Systems” is announced, but before “Reached target System Initialization”. Looking at a system log before adding these “nofail” options, all mounts were made before “Reached target Local File Systems”.

So what happens here? It’s worth mentioning that in local-fs.target, it only says After=local-fs-pre.target in relation to temporal dependencies. So that can explain why “Reached target Local File Systems” is announced before all mounts have been completed.

But then, local-fs.target is listed in sysinit.target’s After= as well as Wants= directives. I haven’t found any clear-cut definition to whether “After=” waits until all “wanted” units have been fully started (or officially failed). The term that is used in “man systemd.unit” in relation to waiting is “finished started up”, but what does that mean exactly? This manpage also says “Most importantly, for service units start-up is considered completed for the purpose of Before=/After= when all its configured start-up commands have been invoked and they either failed or reported start-up success”. But what about “want” relations?

So I guess systemd interprets the “After” directive on local-fs.target in sysinit.target as “wait for local-fs.target’s temporal dependencies as well, even if local-fs.target doesn’t wait for them”.

Querying dependencies

So how can we know which unit depends on which? In order to get the system’s tree of dependencies, go

$ systemctl list-dependencies

This recursively shows the dependency tree that is created by Requires, RequiredBy, Wants, WantedBy and similar relations. Usually, only target units are followed recursively. In order to display the entire tree, add the –all flag.

The units that are listed are those that are required (or “wanted”) in order to reach the target that is being queried (“default.target” if no target specified).

As can be seen from the output, the filesystem mounts are made in order to reach the local-fs.target target. To get the tree of only this target:

$ systemctl list-dependencies local-fs.target

The output of this command are the units that are activated for the sake of reaching local-fs.target. “-.mount” is the root mount, by the way.

It’s also possible to obtain the reverse dependencies with the –reverse flag. In other words, in order to see which targets rely on a local-fs.target, go

$ systemctl list-dependencies --reverse local-fs.target

list-dependencies doesn’t make a distinction between “required” or “wanted”, and neither does it show the nuances of the various other possibilities for creating dependencies. For this, use “systemctl show”, e.g.

$ systemctl show local-fs.target

This lists all directives, explicit and implicit, that have been made on this unit. A lot of information to go through, but that’s the full picture.

If the –after flag is added, the tree of targets with an After= directive (and other implicit temporal dependencies, e.g. mirrored Before= directives) is printed out. Recall that this only tells us something about the order of execution, and nothing about which unit requires which. For example:

$ systemctl list-dependencies --after local-fs.target

Likewise, there’s –before, which does the opposite.

Note that the names of the flags are confusing: –after tells us about the targets that are started before local-fs.target, and –before tells us about the targets started after local-fs.target. The rationale: The spirit of list-dependencies (without –reverse) is that it tells us what is needed to reach the target. Hence following the After= directives tells us what had to be before. And vice versa.

Red herring #1

After this long general discussion about dependencies, let’s go back to the original problem: The mnt-tfcard.mount unit failed with status “dependency” and dev-mmcblk0p1.device had the status inactive / dead.

Could this be a dependency thing?

# systemctl list-dependencies dev-mmcblk0p1.device
dev-mmcblk0p2.device
 └─mnt-tfcard.mount
# systemctl list-dependencies mnt-tfcard.mount
mnt-tfcard.mount
 ├─dev-mmcblk0p1.device
 └─system.slice

Say what? dev-mmcblk0p2.device depends on mnt-tfcard.mount? And even more intriguing, mnt-tfcard.mount depends on dev-mmcblk0p2.device, so it’s a circular dependency! This must be the problem! (not)

This was the result regardless of whether I used /etc/fstab or my own mount unit file instead. I also tried adding DefaultDependencies=no on mnt-tfcard.mount’s unit file, but that made no difference.

Neither did this dependency go away when the last parameter in /dev/fstab was changed from 0 to 2, indicating that fsck should be run on the block device prior to mount. The dependency changed, though. What did change was mnt-tfcard.mount’s dependencies, but that’s not the problem.

# systemctl list-dependencies mnt-tfcard.mount
mnt-tfcard.mount
 ├─dev-mmcblk0p1.device
 ├─system.slice
 └─systemd-fsck@dev-mmcblk0p1.service
# systemctl list-dependencies systemd-fsck@dev-mmcblk0p1.service
systemd-fsck@dev-mmcblk0p1.service
 ├─dev-mmcblk0p1.device
 ├─system-systemd\x2dfsck.slice
 └─systemd-fsckd.socket

But the thing is that the cyclic dependency isn’t an error. This is the same queries on the /boot mount (/dev/sda1, ext4) of another computer:

$ systemctl list-dependencies boot.mount
boot.mount
 ├─-.mount
 ├─dev-disk-by\x2duuid-063f1689\x2d3729\x2d425e\x2d9319\x2dc815ccd8ecaf.device
 ├─system.slice
 └─systemd-fsck@dev-disk-by\x2duuid-063f1689\x2d3729\x2d425e\x2d9319\x2dc815ccd8ecaf.service

And the back dependency:

$ systemctl list-dependencies 'dev-disk-by\x2duuid-063f1689\x2d3729\x2d425e\x2d9319\x2dc815ccd8ecaf.device'
dev-disk-by\x2duuid-063f1689\x2d3729\x2d425e\x2d9319\x2dc815ccd8ecaf.device
 └─boot.mount

The mount unit depends on the device unit and vice versa. Same thing, but this time it works.

Why does the device unit depend on the mount unit, one may ask. Not clear.

Red herring #2

At some point, I thought that the reason for the problem was that the filesystem’s “dirty bit” was set:

# fsck /dev/mmcblk0p1 
fsck from util-linux 2.27.1
fsck.fat 3.0.28 (2015-05-16)
0x25: Dirty bit is set. Fs was not properly unmounted and some data may be corrupt.
1) Remove dirty bit
2) No action

By the way, using “fsck.vfat” instead of just “fsck” did exactly the same. The former is what the systemd-fsck service uses, according to the man page.

But this wasn’t the problem. Even after removing the dirty bit, and with fsck reporting success, dev-mmcblk0p1.device would not start.

The really stinking fish

What really is fishy on the system is this output of “systemctl –all”:

dev-mmcblk0p2.device      loaded activating tentative /dev/mmcblk0p2

/dev/mmcblk0p2 is the partition that is mounted as root! It should be “loaded active plugged”! All devices have that status, except for this one.

Lennart Poettering (i.e. the horse’s mouth) mentions that “If the device stays around in “tentative” state, then this indicates that a device appears in /proc/self/mountinfo with some name, and systemd can’t find a matching device in /sys for it, probably because for some reason it has a different name”.

And indeed, this is the relevant row in /proc/self/mountinfo:

16 0 179:2 / / rw,relatime shared:1 - ext4 /dev/root rw,data=ordered

So the root partition appears as /dev/root. This device file doesn’t even exist. The real one is /dev/mmcblk0p2, and it’s mentioned in the kernel’s command line. On this platform, Linux boots without any initrd image. The kernel mounts root by itself, and takes it from there.

As Lennart points out in a different place, /dev/root is a special creature that is made up in relation to mounting a root filesystem by the kernel.

At this point, I realized that I’m up against a quirk that has probably been solved silently during the six years since the relevant distribution was released. In other words, no point wasting time looking for the root cause. So this calls for…

The workaround

With systemd around, writing a service is a piece of cake. So I wrote a trivial service which runs mount when it’s started and umount when it’s stopped. Not a masterpiece in terms of software engineering, but it gets the job done without polluting too much.

The service file, /etc/systemd/system/mount-card.service is as follows:

[Unit]
Description=TF card automatic mount

[Service]
ExecStart=/bin/mount /dev/mmcblk0p1 /mnt/tfcard/
ExecStop=/bin/umount /mnt/tfcard/
Type=simple
RemainAfterExit=yes

[Install]
WantedBy=local-fs.target

Activating the service:

# systemctl daemon-reload
# systemctl enable mount-card
Created symlink from /etc/systemd/system/local-fs.target.wants/mount-card.service to /etc/systemd/system/mount-card.service.

And reboot.

The purpose of “RemainAfterExit=yes” is to make systemd consider the service active even after the command exits. Without this row, the command for ExecStop runs immediately after ExecStart, so the device is unmounted immediately after it has been mounted. Setting Type to oneshot doesn’t solve this issue, by the way. The only difference between “oneshot” and “simple” is that oneshot delays the execution of other units until it has exited.

There is no need to add an explicit dependency on the existence of the root filesystem, because all services have an implicit Required= and After= dependency on sysinit.target, which in turn depends on local-fs.target. This also ensures that the service is stopped before an attempt to remount root as read-only during shutdown.

As for choosing local-fs.target for the WantedBy, it’s somewhat questionable, because no service can run until sysinit.target has been reached, and the latter depends on local-fs.target, as just mentioned. More precisely (citing “man systemd.service”), “service units will have dependencies of type Requires= and After= on sysinit.target, a dependency of type After= on basic.target”. So this ensures that the service is started after the Basic Target has been reached and shuts down before this target is shut down.

That said, setting WantedBy this way is a more accurate expression of the purpose of this service. Either way, the result is that the unit is marked for activation on every boot.

I don’t know if this is the place to write “all well that ends well”. I usually try to avoid workarounds. But in this case it was really not worth the effort to insist on a clean solution. Not sure if it’s actually possible.

Remapping keyboard keys to allow å, ä and ö

Motivation

I have an English / Hebrew keyboard, but occasionally I also want to use the Swedish letters å, ä and ö. So idea is to sacrifice three keys on the keyboard for this purpose.

But which ones? So I went for the keypad’s /, * and – keys. But hey, I use these normally every now and then.

So why not use these keys with Alt to produce the desired letters? Here’s a simple reason: I don’t know how to do that. What I managed to achieve with xmodmap isn’t sensitive to Alt. Only Shift.

And why not use the keys that are commonly used in Swedish keyboards? Because the relevant keys are used for colon and double quotes. These are useful in Swedish as well. This is normally solved by using the right-Alt button to select the Swedish letters. But as just mentioned, I didn’t find the way to use Alt buttons as a modifier.

And why don’t I just install the Swedish keyboard layout? I might do that later on, but right now I don’t use Swedish often enough to justify another language candidate. It makes language switching more cumbersome.

So my solution was to write simple bash scripts that turn the said keys into å, ä and ö, and another bash script that bring them back to their default use. I’m sure there’s a way to fix it nicely with the Alt key, but I won’t bother.

All here relates to Linux Mint 19 running Cinnamon.

Making changes

First thing first: Save the current setting, in case you mess up:

$ xmodmap -pke > default-mapping.txt

Now let’s look at the default situation. Start with the mapping of modifiers:

$ xmodmap
xmodmap:  up to 4 keys per modifier, (keycodes in parentheses):

shift       Shift_L (0x32),  Shift_R (0x3e)
lock        Caps_Lock (0x42)
control     Control_L (0x25),  Control_R (0x69)
mod1        Alt_L (0x40),  Alt_R (0x6c),  Meta_L (0xcd)
mod2        Num_Lock (0x4d)
mod3
mod4        Super_L (0x85),  Super_R (0x86),  Super_L (0xce),  Hyper_L (0xcf)
mod5        ISO_Level3_Shift (0x5c),  Mode_switch (0xcb)

To get the current keyboard mapping, try

$ xmodmap -pk | less
$ xmodmap -pke | less

The output is a list of keycode commands. Let’s look at one row:

keycode  42 = g G hebrew_ayin G U05F1

The number is the code of the physical key 42 on the keyboard.

That is followed by a number of keysyms. The first is with no modifier pressed, the second with Shift, the third when Mode_switch is used, and the forth is Switch + Mode_switch.

In my case, Mode_switch is when the language is changed to Hebrew, which is why “hebrew_ayin” is listed.

The fifth code, U05F1, is a Unicode character U+05F1, a Hebrew ligature character (ױ). Not clear what that’s for.

According to the man page, there may be up to 8 keysyms, but most X servers rarely use more than four. However, looking at the output of “xmodmap -pke”, there are 10 keysyms allocated to the function keys (F1, F2, etc.). Once again, not clear what for.

If the number codes aren’t clear, use this command to obtain X events. The keycodes are printed out (among all the mumbo-jumbo, it says e.g. “keycode 82″)

$ xev

This utility opens a small windows and dumps all X events that it gets. So this small window must have focus so that the keyboard events are directed to it.

What do these keysyms mean?

I tried this on keycode 90, which is the keypad’s zero or Ins key. Its assignment is originally

keycode  90 = KP_Insert KP_0 KP_Insert KP_0

So I changed it with

$ xmodmap -e "keycode 90 = a b c d e f g h i j"

This command takes a couple of seconds to execute, presumably because the server generates a MappingNotify event on every client each time a keycode assignment is evaluated. So it’s really slow, but it works.

After this, pressing this character plainly now just printed out “a”. No I could test a whole lot of combinations to find out what each of these positions mean:

  1. No modifier.
  2. Shift
  3. Hebrew mode on
  4. Hebrew mode on + Shift

No surprise here. As for the rest of the keysyms, I didn’t manage to get any of the e-j letter to appear, no matter what combination I tried. So I guess they’re not relevant in my setting. The man page was correct: Only four of them are actually used.

By the way, when applying Caps Lock, I got the uppercase version of the same letters. It’s really twisted.

Reverting my change from above:

$ xmodmap -e "keycode 90 = KP_Insert KP_0 KP_Insert KP_0"

The scripts

To reiterate, the purpose is to turn the keypad’s /, *, – into å, ä and ö.

Their respective 106, 63 and 82 (that was pretty random, wasn’t it?), with the following defaults:

keycode 106 = KP_Divide KP_Divide KP_Divide KP_Divide KP_Divide KP_Divide XF86Ungrab KP_Divide KP_Divide XF86Ungrab
keycode  63 = KP_Multiply KP_Multiply KP_Multiply KP_Multiply KP_Multiply KP_Multiply XF86ClearGrab KP_Multiply KP_Multiply XF86ClearGrab
keycode  82 = KP_Subtract KP_Subtract KP_Subtract KP_Subtract KP_Subtract KP_Subtract XF86Prev_VMode KP_Subtract KP_Subtract XF86Prev_VMode

So this is the script to bring back the buttons to normal (which I named “kbnormal”):

#!/bin/bash

echo "Changing the keymap to normal."
echo "The display will now freeze for 7-8 seconds. Don't worry..."
sleep 0.5

/usr/bin/xmodmap - <<EOF
keycode 106 = KP_Divide KP_Divide KP_Divide KP_Divide KP_Divide KP_Divide XF86Ungrab KP_Divide KP_Divide XF86Ungrab
keycode  63 = KP_Multiply KP_Multiply KP_Multiply KP_Multiply KP_Multiply KP_Multiply XF86ClearGrab KP_Multiply KP_Multiply XF86ClearGrab
keycode  82 = KP_Subtract KP_Subtract KP_Subtract KP_Subtract KP_Subtract KP_Subtract XF86Prev_VMode KP_Subtract KP_Subtract XF86Prev_VMode
EOF

And finally, this is the script that turns these buttons into å, ä and ö:

#!/bin/bash

echo "Changing the keymap to swedish letters on numpad's /, *, -"
echo "The display will now freeze for 7-8 seconds. Don't worry..."
sleep 0.5

/usr/bin/xmodmap - <<EOF
keycode 106 = aring Aring aring Aring
keycode  63 = adiaeresis Adiaeresis adiaeresis Adiaeresis
keycode  82 = odiaeresis Odiaeresis odiaeresis Odiaeresis
EOF

The change is temporary, and that’s fine for my purposes. I know a lot of people have been struggling with making the changes permanent, and I have no idea how to do that, nor do I have any motivation to find out.

See the notification that the screen will freeze for a few seconds? It’s for real. The mouse pointer keeps running normally, but the desktop freezes completely for a few seconds, including the clock.

That rings an old bell. Like, a six years old bell. I’ve been wondering why moving the mouse pointer in and out from a VMWare window causes the entire screen to freeze for a minute. Maybe it has to do with keyboard mapping? It’s quite plausible that moving the mouse off the virtual machine’s window would require a different keymap. Haven’t investigated this further.

Notes on ZTE ZXHN F601 GPON ONT

Introduction

These are my notes while setting up ZTE’s ONT for GPON on a Linux desktop computer. I bought this thing from AliExpress at 20 USD, and got a cartoon box with the ONT itself, a power supply and a LAN cable.

This is a follow-up from a previous post of mine. I originally got a Nokia ONT when the fiber was installed, but I wanted an ONT that I can talk with. In particular, one that gives some info about the fiber link. Just in case something happens.

The cable of the 12V/0.5A power supply was too short for me, so I remained with the previous one (from Nokia’s ONT).

The software version of the ONT is V6.0.1P1T12 out of the box, which is certified by Bezeq. Couldn’t be better.

By default, this ONT acts as a GPON to Ethernet bridge. However, judging by its menus on the browser interface, it can also act as a router with one Ethernet port: If so requested, it apparently takes care of the PPPoE connection by itself, and is capable of supplying the whole package that comes with a router: NAT, a firewall, a DHCP server, a DNS and whatnot. I didn’t try any of this, so I don’t know how well it works. But it’s worth to keep these possibilities in mind.

In order to reset the ONT’s settings to the default values, press the RESET button with a needle for at least five seconds while the device is on (according to the user manual, didn’t try this).

So how come this thing isn’t sold at ten times the price, rebranded by some big shot company? I think the reason is this:

The PON LED is horribly misleading

According to the user guide, the PON LED is off when the registration has failed, blinking when registration is ongoing, and steadily on when registration is successful.

The problem is that registration doesn’t mean authentication. In other words, the fact that the PON LED is steadily on doesn’t mean that the other side (the OLT) is ready to start a PPPoE session. In particular, if the PON serial number is not set up correctly, the PON LED will be steadily on, even though the fiber link provider has rejected the connection.

Nokia’s modem’s PON led will blink when the serial number is wrong, and it makes sense: The PON is not good to go unless the authentication is successful. I suppose most other ONTs behave this way.

The only way to tell is through the browser interface. More about this below.

Browser interface

The ONT responds to pings and http at port 80 on address 192.168.1.1. A Chinese login screen appears. Switch language by clicking on where is says “English” at the login box’ upper right corner.

The username and password are both “admin” by default.

As already mentioned, this ONT has a lot of features. For me, there were two important ones: The ability to change the PON serial number, so I can replace ONTs without involving my ISP, and the ability to monitor the fiber link’s status and health. This can be crucial when spotting a problem:

Fiber link information on browser interface of ZTE ZXHN F601 GPON ONT

(click to enlarge)

Note that in this screenshot, the GPON State is “Authentication Success”. This is what it should be. If it says “Registration Complete”, it means that the ONT managed through a few stages in the setup process, but the link isn’t up yet: The other side probably rejected the serial number (and/or the password, if such is used). And by the way, when the fiber wasn’t connected at all, it said “Init State”.

Also note the input power, around -27 dBm in my case. It depends on a lot of factors, among others the physical distance to the other fiber transmitter. It can also change if optical splitters are added or removed on the way. All this is normal. But each such change indicates that something has happened on the optical link. So it’s a good way to tell if people are fiddling with the optics, for better and for worse.

These are the changes I made on my box, relative to the default:

  • I turned the firewall off at Security > Firewall (was at “Low”). It’s actually possible to define custom rules, most likely based upon iptables. I don’t think the firewall operates when the ONT functions as a bridge, but just to be sure it won’t mess up.
  • In Security > Service Control, there’s an option for telnet access from WAN. Removed it.
  • In BPDU, disabled BPDU forwarding.

I don’t think any of these changes make any difference when using the ONT as a bridge.

Setting the PON serial number

Note to self: Look for a file named pon-serial-numbers.txt for the previous and new PON serial numbers.

When I first connected the ONT to the fiber, I was surprised to see that the PON LED flashed and then went steady. Say what? The network accepted the ONT’s default serial number without asking any questions?

I then looked at the “PON inform” status page (Status > Network Interface > PON Inform), and it said “Registration Complete”. Wow. That looked really reassuring. However, pppd was less happy with the situation. In fact, it had nobody to talk with:

Aug 06 10:56:21 pppd[36167]: Plugin rp-pppoe.so loaded.
Aug 06 10:56:21 pppd[36167]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.5
Aug 06 10:56:21 pppd[36168]: pppd 2.4.5 started by root, uid 0
Aug 06 10:56:56 pppd[36168]: Timeout waiting for PADO packets
Aug 06 10:56:56 pppd[36168]: Unable to complete PPPoE Discovery
Aug 06 10:56:56 pppd[36168]: Exit.

Complete silence from the other side. I was being ignored bluntly.

Note that I’m discussing the PPPoE topic in another post of mine.

Solution: I went into the Network > PON > SN menu in the browser interface, and copied the serial number that was printed on my previous ONT in full. It was something like ALCLf8123456. That is, four capital letters, followed by 8 hex digits. There’s also a place to fill in the password. Bezeq’s fiber network apparently doesn’t use a password, so I just wrote “none”. Clicked the “Submit” button, the ONT rebooted (it takes about a minute), and after that the Internet connection was up and running.

And of course, the GPON State appeared as “Authentication Success” in the “POD Inform” page.

So don’t trust the PON LED, and don’t get deceived by the words “Registration Complete”. Unless you feed the serial number that the fiber network provider expects, there’s nobody talking with you.

In fact, there’s an option in browser interface to turn off the LEDs altogether. It seemed like a weird thing to me at first, but maybe this is the Chinese workaround for this issue with the PON LED.

Bottom line

With the Internet link up and running, I ran a speed test. Exactly the same as the Nokia ONT.

So the final verdict is that this a really good ONT, which provides a lot of features and information. The only problem it apparently has is the confusing information regarding the PON link’s status when the serial number is incorrect. Which is probably the reason why this cute thing remains a Chinese no-name product.

http referer info missing in Apache logs for a non-https site

I checked my Apache access logs, and noted that I saw no indications for people clicking links between two of my websites. It was extremely odd, because it was quite clear that at least a few such clicks should happen.

In the beginning, I though it was because of the rel=”noopener” part in the link. It shouldn’t have anything to do with this, but maybe it did? So no, that wasn’t the problem.

The issue was that if the link goes from an https site to a non-https site, the referer is blank. Why? Not 100% clear, but this is what Mozilla’s guidelines says. It has probably to do with pages with sensitive URLs (e.g. pages for resetting passwords). If the URL leaks through a non-secure http link (say, to a third-party server that supplies images, fonts and other stuff for the page), an eavesdropping attacker might get access to this URL.

And it so happens that this blog is a non-https site as of writing this. Mainly because I’m lazy.

On the other hand, when you read this, the site has been moved to https. Lazy or not, the missing referrer was the motivation I needed to finally do this.

Was it worth the effort? Well, so-so. Both Chrome nor Firefox submit a blank referrer if the link was non-https, even if a redirection to an https address is made. In other words, all existing links to a plain http address will remain hidden. But new links are expected to be based upon https, so at least they will be visible.

Well, partly: My own anecdotal test showed that Firefox indeed submits the full URL of the referrer for an https link, but Chrome gives away only the domain of the linking site. This is more secure of course: Don’t disclose a sensitive URL to a third party. And also, if you want to know who links to your page, go to Google’s search console. So chopping off the referrer also server Google to some extent.

Bottom line: It seems like the Referer thing is slowly fading away.

PPPoE on fiber with the Linux machine as the router

Introduction

Having switched from ADSL to FTTH (fiber to the home), I was delighted to discover that the same script that set up the pppoe connection for ADSL also works with the new fiber connection. And as the title of this post implies, I opted out the external router that the ISP provided, and instead my Linux desktop box does the pppoe stuff. Instead, I went for a simple ONT (“fiber bridge”) which relays Ethernet packets between the fiber and an Ethernet jack.

This post is a spin-off from another post of mine, which discusses the transition to fiber in general.

Why am I making things difficult, you may ask? Actually, if you’re reading this there’s a good chance that you want to do the same, but anyhow: The reason for opting out an external router is the possibility to apply a sniffer on the pppoe negotiation if something goes wrong. To be able to tell the difference between rejected credentials and an ISP that doesn’t talk with me at all. This might hopefully help bringing back the link quicker if and when.

But then it turned out that even though the old setting works, the performance is quite bad: It was all nice when the data rate was limited to 15 Mb/s, but 1000 Mb/s is a different story.

So here’s my own little cookbook to pppoe for FTTH on a Linux desktop.

The “before”

The commands I used for ADSL were:

/usr/sbin/pppd pty /usr/local/etc/ADSL-pppoe linkname ADSL-$$ user "myusername@013net" remotename "10.0.0.138 RELAY_PPP1" defaultroute netmask 255.0.0.0 mtu 1452 mru 1452 noauth lcp-echo-interval 60 lcp-echo-failure 3 nobsdcomp usepeerdns

such that /usr/local/etc/ADSL-pppoe reads:

#!/bin/bash
/usr/sbin/pppoe -p /var/run/pppoe-adsl.pid.pppoe -I eth1 -T 80 -U  -m 1412

And of course, replace myusername@013net with your own username and assign the password in /etc/ppp/pap-secrets. Hopefully needless to say, the ADSL modem was connected to eth1.

This ran nicely for years with pppd version 2.4.5 and PPPoE Version 3.10, which are both very old. But never mind the versions of the software. pppoe and pppd are so established, that I doubt any significant changes have been made over the last 15 years or so.

Surprisingly enough, I got only 288 Mb/s download and 100 Mb/s upload on Netvision’s own speed test. The download speed should have been 1000 Mb/s (and the upload speed is as expected).

I also noted that pppoe ran at 75% CPU during the speed test, which made me suspect that it’s the bottleneck. Spoiler: It indeed was.

I tried a newer pppd (version 2.4.7) and pppoe (version 3.11) but that made no difference. As one would expect.

Superfluous options

Note that pppd gets unnecessary options that set the MTU and MRU to 1452 bytes. I suspected that these were the reason for pppoe working hard, so I tried without them. But there was no difference. They are redundant nevertheless.

Then we have the ‘remotename “10.0.0.138 RELAY_PPP1″ ‘ part, which I frankly don’t know why it’s there. Probably a leftover from the ADSL days.

Another thing is pppoe’s “-m 1412″ flag, which causes pppoe to mangle TCP packets with the SYN flag set, so that their MSS option is set to 1412 bytes, and not what was originally requested.

A quick reminder: The MSS option is the maximal size of IP packets that we can receive from the TCP stack on the other side. This option is used to tell the other side not to create TCP packets larger than this, in order to avoid fragmentation of arriving packets.

It is actually a good idea to mangle the MSS on outgoing TCP packets, as explained further below. But the 1412 bytes value is archaic, copied from the pppoe man page or everyone copies from each other. 1452 is a more sensible figure. But it doesn’t matter all that much, because I’m about to scrap the pppoe command altogether. Read on.

Opening the bottleneck

The solution is simple: Use pppoe in the kernel.

There’s a whole list of kernel modules that need to be available (or compiled into the kernel), but any sane distribution kernel will have them included. I suppose CONFIG_PPPOE is the kernel option to check out.

The second thing is that pppd should have the rp-pppoe.so plugin available. Once again, I don’t think you’ll find a distribution package for pppd without it.

With these at hand, I changed the pppd command to:

/usr/sbin/pppd plugin rp-pppoe.so eth1 linkname ADSL-$$ user "myusername@013net" defaultroute netmask 255.0.0.0 noauth lcp-echo-interval 60 lcp-echo-failure 3 nobsdcomp usepeerdns

That’s exactly the same as above, but instead of the “pty” option that calls an external script, I use the plugin to talk with eth1 directly. No pppoe executable to eat CPU, and the transmission speed goes easily up to >900 Mb/s without any dramatic CPU consumption visible (“top” reports 8% system CPU at worst, and that’s global to all CPUs).

I also removed the options for setting MTU and MRU in the pppd command. ppp0 now presents an MTU of 1492, which I suppose is correct. I mean, why fiddle with this? And I ditched the “remotename” option too.

Once again, the ONT (“fiber bridge”) was connected to eth1.

Samples of log output

This is the comparison between pppd’s output with pppoe as an executable and with the kernel’s pppoe module:

First, the old way, with pppoe executable:

Using interface ppp0
Connect: ppp0 <--> /dev/pts/13
PAP authentication succeeded
local  IP address 109.186.24.16
remote IP address 212.143.8.104
primary   DNS address 194.90.0.1
secondary DNS address 212.143.0.1

And with pppoe inside the kernel:

Plugin rp-pppoe.so loaded.
RP-PPPoE plugin version 3.8p compiled against pppd 2.4.5
PPP session is 3865
Connected to 00:1a:f0:87:12:34 via interface eth1
Using interface ppp0
Connect: ppp0 <--> eth1
PAP authentication succeeded
peer from calling number 00:1A:F0:87:12:34 authorized
local  IP address 109.186.4.18
remote IP address 212.143.8.104
primary   DNS address 194.90.0.1
secondary DNS address 212.143.0.1

The MAC address that is mentioned seems to be owned by Alcatel-Lucent, and is neither my own host’s or the ONT’s (i.e. the “fiber adapter”). It appears to belongs to the link partner over the fiber connection.

And by the way, if the ISP credentials are incorrect, the row saying “Connect X <–> Y” is followed by “LCP: timeout sending Config-Requests” after about 30 seconds. Instead of “PAP authentication succeeded”, of course.

Clamping MSS

The pppoe user-space utility had this nice “-m” option that caused all TCP packets with a SYN to be mangled, so that their MSS field was set as required for the pppoe link. But now I’m not using it anymore. How will the MSS field be correct now?

First of all, this is not an issue for packets that are created on the same computer that runs pppd. ppp0′s MTU is checked by the TCP stack, and the MSS is set correctly to 1452.

But forwarded packets come from a source that doesn’t know about ppp0′s reduced MTU. That host sets the MSS according to the NIC that it sees. It can’t know that this MSS may be too large for the pppoe link in the middle.

The solution is to add a rule in the firewall that mangles these packets:

iptables -A FORWARD -o ppp0 -t mangle -p tcp --tcp-flags SYN,RST SYN -j TCPMSS --clamp-mss-to-pmtu

This is more or less copied from iptables’ man page. I added the -o part, because this is relevant only for packets going out to ppp0. No point mangling all forwarded packets.

A wireshark dump

This is what wireshark shows on the Ethernet card that is connected to the ONT during a successful connection to the ISP. It would most likely have looked the same on an ADSL link.

No.     Time           Source                Destination           Protocol Length Info
      3 0.142500324    Dell_11:22:33         Broadcast             PPPoED   32     Active Discovery Initiation (PADI)
      4 0.144309286    Alcatel-_87:12:34     Dell_11:22:33         PPPoED   60     Active Discovery Offer (PADO) AC-Name='203'
      5 0.144360515    Dell_11:22:33         Alcatel-_87:12:34     PPPoED   52     Active Discovery Request (PADR)
      6 0.146062649    Alcatel-_87:12:34     Dell_11:22:33         PPPoED   60     Active Discovery Session-confirmation (PADS)
      7 0.147037263    Dell_11:22:33         Alcatel-_87:12:34     PPP LCP  36     Configuration Request
      8 0.192272315    Alcatel-_87:12:34     Dell_11:22:33         PPP LCP  60     Configuration Request
      9 0.192290554    Alcatel-_87:12:34     Dell_11:22:33         PPP LCP  60     Configuration Ack
     10 0.192335094    Dell_11:22:33         Alcatel-_87:12:34     PPP LCP  40     Configuration Ack
     11 0.192516908    Dell_11:22:33         Alcatel-_87:12:34     PPP LCP  30     Echo Request
     12 0.192660752    Dell_11:22:33         Alcatel-_87:12:34     PPP PAP  50     Authenticate-Request (Peer-ID='myusername@013net', Password='mypassword')
     13 0.201978697    Alcatel-_87:12:34     Dell_11:22:33         PPP LCP  60     Echo Reply
     14 0.309272346    Alcatel-_87:12:34     Dell_11:22:33         PPP PAP  60     Authenticate-Ack (Message='')
     15 0.309286268    Alcatel-_87:12:34     Dell_11:22:33         PPP IPCP 60     Configuration Request
     16 0.309289064    Alcatel-_87:12:34     Dell_11:22:33         PPP IPV6CP 60     Configuration Request
     17 0.309398416    Dell_11:22:33         Alcatel-_87:12:34     PPP IPCP 44     Configuration Request
     18 0.309429731    Dell_11:22:33         Alcatel-_87:12:34     PPP IPCP 32     Configuration Ack
     19 0.309441755    Dell_11:22:33         Alcatel-_87:12:34     PPP LCP  42     Protocol Reject
     20 0.315313539    Alcatel-_87:12:34     Dell_11:22:33         PPP IPCP 60     Configuration Nak
     21 0.315365821    Dell_11:22:33         Alcatel-_87:12:34     PPP IPCP 44     Configuration Request
     22 0.321070570    Alcatel-_87:12:34     Dell_11:22:33         PPP IPCP 60     Configuration Ack

These “Configuration Request” and “Configuration Ack” packets contain a lot of data, of course: This is where the local and remote IP addresses are given, as well as the addresses to the DNSes.

Some random notes

  • On a typical LAN connection over Ethernet, MSS is set to 1460. The typical value for a pppoe connection is 1452, 8 bytes lower.
  • Add “nodetach” to pppd’s command for a (debug) foreground session.
  • Add “dump” to pppd’s command to see all options in effect (from option file and command line combined).

Internet fiber optics in Israel: The gory technical details

Introduction

In July 2023 I finally decided to ditch my ADSL connection and upgrade to fiber optics (FTTH). Living in Israel, the whole thing gets a bit complicated, because there’s a separation between the infrastructure provider and the ISP. In other words, the fiber connections is supplied by company A, which brings the connection to the doorsteps of company B, the ISP, which takes care of the connection to the world. A and B can be the same company, but they often aren’t.

In my case, Bezeq is the provider of the fiber connection itself, and I’ve chosen Netvision / Cellcom as the ISP. The technical details below may be significantly different for you, in particular if another company has done the fiber infrastructure. There seems to be a lot of confusion regarding the infrastructure part, possibly because different service providers do things differently. I don’t know. This post is all about my own Internet connection.

There are three reasons why I got so involved in the gory details of this:

  1. It pays off in the long run. In particular, on that day when the Internet link falls, you call customer support and they are clueless (as always). If I can figure out what the problem is based upon my understanding of the system and the information that my own equipment provides, the link has a chance to get back quickly. Otherwise, good luck. And yes, it’s their job to know what they’re doing, but that’s nice in theory.
  2. There was some problem with ordering the service. It’s not clear exactly why, but it seems like a new fiber splitter was needed in the floor connection box (more on that below). It took a month from my first phone call to the actual installation.
  3. This stuff is actually interesting, and somewhat related to things I do for a living. I didn’t become an electrical engineer for nothing.

Reason #1 above implies working with equipment that exposes technical information. Sweet-talking routers that are configured automatically by virtue of a mobile phone app may be quick to set up, but then go figure what’s going on when something goes wrong. The fiber front-end should be as simple as possible and yet provide diagnostic information, at best.

Acronyms

I’m going to use these, so let’s get this over with:

  • PON (Passive optical network) is the standard that arranges fiber connections in a one-to-many topology.
  • GPON: Gigabit-capable PON. A standard on top of PON, which makes it capable for carrying Gigabit Ethernet.
  • ONT: Optical Network Terminal. That is the little box we have in our homes. Sometimes called “fiber modem”, “fiber adapter”. Even a router is some kind of ONT.
  • OLT: Optical Line Terminal: That’s the electronics that is connected to the fiber somewhere in the company’s premises.
  • FTTH: Fiber to the home. A commercial term with obvious meaning.

The technical details in brief

The fiber connection is GPON. I’m discussing this to painstaking detail below, so for now we’ll do with the fact that only one fiber is used for full-duplex communication. Unlike the SFP+ configuration I’m used to, which carries two fibers with a slinky feel, and usually connects with a dual connector, a GPON fiber looks like a somewhat rigid wire, and has a connector with a square shape.

But the most important technical detail is that pppoe is used. Effectively, the look and feel is exactly like ADSL, only it’s faster. Just like with ADSL, you get a username and a password. If you have a router, the credentials go there. But if you opted that out like I did, and instead went for an simple ONT (a.k.a. “fiber adapter”, “ONT bridge”, “fiber modem”), the computer needs to do the pppoe stuff (or maybe an pppoe-capable router, but what’s the point?).

As it turns out, the only thing I needed to change in my existing pppoe setting was the username and password.

Well, no. Doing that is enough to get a working Internet connection with an impressive data rate, but not even close to the advertised rate. To attain that, I had to switch to using the kernel’s pppoe module, as detailed in a separate post.

As a side note, my original plan was to have ADSL and fiber optics running for a month in parallel, just to be safe. But as soon as I got the fiber account activated (see below), the ADSL stopped working. Even though I asked explicitly to keep both accounts active in parallel, and even though the username for fiber was different from the one I used for ADSL (albeit very similar), ADSL got knocked down. I guess I asked for too much. Because it went so easily with the fiber, I wasn’t in the mood to waste time on ensuring redundancy.

Speed tests

There are two interesting sites for this:

  • Netvision’s own speed test. I got 930 Mb/s down and 100 Mb/s up on this test. Quite reasonable.
  • Ookla’s speed test allows choosing which server to run against. So picking Bezeq’s server, for example, I got 500 Mb/s down and 100 Mb/s up. This says nothing more than the connections between Cellcom and Bezeq.

Downloading a huge from from ISOC’s mirror server gave me around 400 Mb/s.

So the 1000 Mb/s figure is nice, but theoretical. And that’s before starting with server’s abroad. For example, downloading a huge file from a server in Germany (which is considered relatively close), the rate began at ~80 Mbit/s, and slowly rose towards 320 Mb/s. Which isn’t bad, actually.

GPON in a nutshell

GPON is a one-to-many framework. It means that the service provider (OLT) broadcasts a single 2.4 Gbit/s downstream signal to all subscribers (up to 128). Optical splitters divide this signal among the physical fibers that reach the subscribers. Likewise, all upstream signals are optically combined on their way to the OLT’s optical sensor. A 1.2 Gbit/s stream is TDMA’ed among the subscribers to avoid collisions. Each frame on the fiber is 125 μs, in both directions.

Each subscriber is connected with only one fiber, with a separate light wavelength for each direction: 1490 nm downstream, 1310 nm upstream (both infrared, hence invisible even with my smartphone’s camera).

The handshake that sets up the GPON link usually takes less than a second, but it involves several stages. During this setup, the ONT’s unique serial number is transmitted to the OLT. This means that the provider of the fiber network service can identify each subscriber, regardless of how the fibers are connected. It also means that if the ONT is replaced with another similar box, there will probably be a need to inform the service provider about the updated serial number, or else it will be rejected.

Like any TDMA protocol, the transmission of upstream data must be orchestrated and synchronized. As there might be significant differences between the fibers’ lengths, a calibration process called ranging takes place soon after the fiber is connected to the ONT. This allows compensating for these differences, and ensure an accurate timing of the upstream frames.

The immediate conclusion is that we share bandwidth with our neighbors. How many neighbors and which ones, that depends on how the optical splitting is made, but in most realistic scenarios, the data bottleneck will not be on the fiber: For now, the Internet itself isn’t all that fast, after all.

But if someone has a faulty ONT that transmits data when it shouldn’t (or say, all the time), this can definitely knock down a few neighbor’s connection. Not likely to happen, and still.

Is the pppoe handshake necessary?

I’ve seen talk about users getting a “DHCP connection” over fiber. It’s not clear if they got confused with the fact that their router at home gave them an IP address, or if some people skip the pppoe thing, and talk with a DHCP server across the fiber link.

Given that the bringup of the GPON link involves the ONT’s identification with its serial number, one could argue that the pppoe negotiation is unnecessary: The OLT knows who it is talking with, based upon the serial number. But skipping pppoe requires that OLT does the pairing with the ISP based upon the serial number, rather than the username (which includes the name of the ISP).

So ditching the pppoe thing is surely possible theoretically, and it would surely make things simpler. I don’t know if it has been done in Israel, though.

The fiber/Ethernet “adapter”

If you read my short discussion about GPON above, you’ve realized that there is no such thing as an “fiber to Ethernet adapter” on a GPON system. It’s an ONT, at it’s a very active device. The word “adapter” would have been suitable had the fiber connection been plain Gigabit Ethernet over fiber, with an SFP+ connector, because in that case the adapter indeed just translates the optical signal into an electrical one. But this is definitely not the case with the fibers I had installed.

To my technician’s disappointment, I didn’t want to take Cellcom’s all-in-one router, but requested what is called an “adapter” or “fiber modem” instead. There’s actually a price reduction for going this way, but this wasn’t my motivation: I want the computer to do the pppoe, so I can see what happens.

So the technician gave me a Nokia 7368 ISAM ONT G-010G-Q. It’s a small box with four LEDs. Looked a bit old and used, actually.

The most important thing to know about this box is that it takes about 60 seconds for this thing to boot after powerup.

During this time, the PON LED remains off no matter what, even if the fiber is connected correctly. After these 60 seconds, the “Alarm” LED (red) gets on briefly, after which the PON LED will also go on (if the fiber is connected). A disconnection of the fiber causes the “Alarm” LED to go on, and PON go off. Reconnecting the fiber reverses this (the PON will flash for a second before getting steady). All this is regardless of the LAN LED, which depends on the Ethernet plug, of course.

So a good way to get confused with this box is to turn it on with the fiber connected, see that PON doesn’t go on, and then start doing things randomly, possibly turning the box off and on again. 60 seconds is longer than most of us expect, and the box doesn’t give any indication that it’s starting up.

Another thing to keep in mind is that when the PON LED flashes, it means that a physical connection has been detected, and the box is busy bringing up the data link. When it stays in this state for a long time, it may be because the OLT (the fiber service provider) doesn’t recognize the ONT’s serial number, and therefore refuses to continue the bringup process. During my installation, this was the situation for quite a few minutes, while the technician was on the phone, reading out the ONT’s serial number, among others.

The disadvantage with this Nokia box is that it apparently has no admin interface on the Ethernet side. So it gives me no diagnostic information.

So I got myself a ZTE F601 for $20 instead. It’s listed in Bezeq’s list of approved ONTs, and it has an administration interface that is accessible with a web browser. This interface allows changing the PON serial number, and a whole lot of other things. I’ve written about ZTE’s ONT in a separate post. Bottom line: It’s a nice thing, and I use it instead of Nokia’s ONT. Apparently, the only drawback it has is that the PON LED can be misleading. I elaborate on that on the said post.

But after three weeks with this ONT, I got a phone call from my ISP. They asked me to move back to the Nokia ONT, or Bezeq would disconnect me. I responded by sending the said list of supported ONTs as well as a screenshot of the web interface screen, which shows that the version is correct. However, that didn’t help: Apparently, Bezeq don’t agree that Cellcom users have something different than what’s listed, and they surely didn’t like that I played with the serial number. Or maybe was it Cellcom who didn’t like my games, and they just blamed Bezeq?

I left a brief complaint at Bezeq’s website, and soon enough I got a phone call from their representative. I explained the situation, and a couple of days later, they were back with a clear message: Bezeq has no problem with my ONT, and they had specifically checked my connection and verified that there had been nothing odd reported regarding it.

So it looks like Cellcom doesn’t like my ONT, and they blamed Bezeq for it. Anyhow, I moved back to the Nokia thingy. ZTE will be used as a fallback and for debugging if necessary. It’s not worth my time and effort to fight about this. And the fact that representatives of communication companies make up stories is not really new.

Fun fact: The PPPoE session remained even after replacing the ONT. There was no need to re-initiate it.

Note to self: I left the firewall rules that allow communication with the ZTE ONT.

Choosing ISP

There are several companies in Israel that offer “Internet over Fiber”. One needs to keep in mind that choosing an ISP has an impact on exactly three factors:

  • The data rate. The ISP supplies the facilities for routing to the traffic to the world. So except for local services (local TV stations etc. or services that have local servers for better performance), it’s the amount of bandwidth that the ISP has purchased for its connection with Europe and USA that matters.
  • The annoyances. Does the ISP block certain types of traffic, for example Bittorrent? Does it “accidentally” disconnect your session in the middle of very long downloads? Does it block certain ports “for your safety”?
  • The customer support. Eventually, you’ll have to call someone. How will that work?

I’ve been a Netvision (Cellcom) customer for a very long time, and I’m pretty satisfied with them. So the natural choice is to stay with them.

I did check with Partner, though. The people I got to talk with were exceptionally unprofessional. The person who called me up in response to my interest was very nice, but had no idea what I talked about when I said that I wanted an “adapter” and not a router. I was then handed over to their more technical guy who told me that nobody offers a fiber connection without a router (something Netvision had already approved they’ll do). So Partner was out, because they only offer their router.

I can actually understand that ISPs want to use their own router. All the technical hocus-pocus (activating the ONT’s serial number + setting up the pppoe username and password) is done with a simple mobile app, when using this kind of router. It also makes it a bit more complicated to move from one ISP to another, because I suppose each company locks its routers to its own services (or at least, doesn’t allow this automatic setup to another service). So even though you are legally free to change ISP, it’s still not something you can do with a simple phone call, and boom, you moved. A technician needs to pay a visit. This slows down the migration process, which gives the losing ISP a chance to do the sweet talk. With a neutral ONT, I can change ISP just like that. To an ISP that doesn’t require their own router, of course.

The third alternative that I checked was Bezeq. Their price was high, and my long-time experience with this company is to have as little as possible to do with them.

But I did consider them because of completely different reason: My first call to Cellcom for installing fiber was a month before the actual installation. On this initial call, the sales shark at the other end said that there’s an infrastructure issue that needs to be solved, and promised to come back to me soon. Two weeks passed, and I tried my luck again. Another guy said basically the same, said that he had begun the process of fixing the infrastructure issue, and then disappeared too. I tried again after a week, and this second guy finally opened a call for a technician to install fiber at my place.

A couple of days later, I got a call from Cellcom. This time they wanted to cancel the technician call, because there were missing details, which indicates an infrastructure problem. I refused, and told them to send a technician, and once he arrives, we’ll figure out why there’s a problem.

Eventually, this technician arrived and made the installation.

But why did it take a month? As I’ll detail below, there were already four fiber subscribers in my building. In order to add another one, there was a need to add another fiber splitter in the connection box at the bottom floor. It looks like it was added during this month, not clear when. But it’s clear who did it: Bezeq. It’s quite likely that Bezeq was reluctant to send their technician to allow the connection of a Cellcom subscriber, or maybe their technicians are busy, so they prioritize their own subscribers.

So had I known then what I know today (see below), I would have looked at the connection box and understood the problem. I would then have requested an installation of Bezeq’s fiber service. One day before the arrival of the technician, I would have checked if they had added the splitter, and if so, canceled the installation. If not, I would have let Bezeq’s technician do the fiber installation, and then switched ISP.

The installation process

The rest of this post is dedicated to the art of connecting fibers. In detail, maybe too much detail.

Note to self: See misc-after-moving-here/fiber-internet directory for a few even more specific details.

I’ll start with pointing out that my technician uses the word for “fiber” (“סיב”) to refer to a fiber cable. He uses the word for “leg” (“רגל”) in reference to a single fiber.

And now to what he actually did: The first step is to draw a single fiber from the requested point inside the apartment to the connection box outside the apartment, but on the same floor. In my case, that consisted of pulling the fiber through the existing cable pipes, side-by-side (or instead of) cables for cable TV and good old analog landline telephone.

As it was done in my case, the fiber just pops out from the lower edge of the telephone line jack’s plastic frame, going straight downwards. Not very elegant, but in my specific setting that’s barely visible.

The next step is to make a male optical connector on both sides of the fiber. There are special tools for that.

At this point, a red laser is connected to the fiber inside the apartment, using the connector. This will be used later.

Now to the connection box outside the apartment: It’s manufactured by Appletec (this is a Youtube video showing how to install it + some fiber soldering and stuff). The idea is that a fiber cable is drawn from a box at the bottom floor to the top floor. On each floor, a number of fibers end at that floor’s connection box, one fiber for each apartment. These fibers are connected to female connectors on this box.

So the fiber from my apartment was connected to the floor’s connection box by mating two connectors. Now there’s an optical connection all the way to the connection box at the bottom floor. This is where all fibers from the building arrive, but even more important, this is where Bezeq’s fiber cable (or cables) arrive from their main switch (which can be literally miles away).

This connection box, which I’ll discuss in detail in the next section, is a patch panel for connecting between the fibers from the house to fibers that are connected to Bezeq. All fibers are connected to female connectors, so in order to connect an apartment to Bezeq, a short fiber cable, with two male connectors, is connected between two points.

The tricky part is to tell which of the fibers in this patch panel is connected to my apartment. Well, not really tricky, because of that red laser that was connected to that fiber inside my apartment. So there’s a clear red light showing which one to go on with.

A sticker with details is put on the fiber in both connection boxes. Both stickers containing the same information. It seems like Cellcom’s method is to write the apartment number, the floor, the “tag” number (“מספר תג”) and the Cellcom customer’s number. Partner appear to write the name of the subscriber and nothing else. I have no idea how Bezeq do their marking, because none of my neighbors was stupid enough to choose them. Anyhow, it’s a matter of time before the bottom connection box becomes a snakesnest. Not to mention that it’s practically accessible to anyone.

The floor level connection box

This box is manufactured by Appletec as well. Here’s a picture of its interior: (click to enlarge)

GPON fiber patch panel box

Quite evidently, this box is divided into a left and right compartment, each having a separate door. The intention is most likely that subscription installers keep themselves to the right side, and the infrastructure guys do their stuff to the left.

The first problem that is tackled at the left side of this box is that the fibers that are packed into a cable are too fragile to handle directly. The solution is to insert the cables into a protected enclosure (which I’ve marked A on the photo). In this closure, fusion splice (which is a bit like soldering or welding) is used to make 1:1 connections between the fragile fibers and fibers that have a mechanical protection shield (a thin coating, similar to electrical wire’s isolation). The latter fibers can then be used for the “wiring”. To get an idea what happens inside this enclosure, check out this Youtube video.

There are two types of cables that arrive to this box: Those from the upper floors and those from Bezeq. All these fibers get into this same little enclosure, get their thing done, and then it’s up to the technician who set up the connection box to not get confused about which fibers are which.

I’ve marked a few highlights in this box’ left side in the photo above:

  • A: Inside this little plastic enclosure, there are 1:1 connections between fibers from cables and the fibers that are used inside the left side of the connection box. Explained above.
  • B: Group of all fibers connected from upper floors (coming from 1:1 connections with cable).
  • C: Group of fibers connected to Bezeq’s cable. There are only two of them.
  • D: This metal rod is one of two 1:4 splitters in the connection box. The blue fiber at this splitter’s bottom comes from one of the fibers at C (it makes a nice loop on the way there), and the four outputs go to the patch panel’s front. The other 1:4 splitter, which was most likely installed earlier, is lying down on the box’ floor, close to the letter C, and is the output of the four white fibers.

So there are two 1:4 splitters in this connection box. The differences in the colors of the fibers and the way they are laid out in the box indicate that they were installed in different occasions. It seems like the one hanging vertically was installed lately in order to allow for my installation, which is the fifth subscriber on this box.

The right side is supposed to be a patch panel. One could have expected some kind of order, like an upper row of fiber connectors for connections to apartments and a lower row for connections to Bezeq. The reality in this box is not just that there’s no visible distinction, but that the genius who set up this box mixed them up completely. Some kind of note on the box saying which connection is what is of course way too much to expect, even though the slots are numbered.

At the moment there are only 8 live fibers from Bezeq available at the patch panel’s front (i.e. the wall between the left and right parts), so it’s quite likely that one of the fibers will have to be split further at a later stage (as my neighbors upgrade to fibers).

But wait. Why are there two fibers coming in a the box’ top-right corner, and another couple at the bottom right? This is supposed to be a patch-panel part, meaning all connections are internal!

The answer is simple: All four fiber subscriber installations were made with the fiber drawn directly from this connection box to the apartments. They simply ignored the connection boxes on each floor, and went directly down to the bottom floor. Why? Probably because the wiring infrastructure in this specific building makes it easier to draw a fiber all the way through, rather than to use the brain.

References

Google Chrome: Stop that nagging on updates

I have Google Chrome installed on a Linux machine at /opt/google as root, so the browser can’t update itself automatically. Instead, it complains with this pop-up every time the browser is started:

Annoying Google Chrome update popup

What I really like about this pop-up is the “you’re missing out” part. I get the same thing from the silly image gallery app on my Google Pixel phone.  This is Google trying to play on my (not so existent) FOMO.

It has been suggested to add the –simulate-outdated-no-au argument to the command line that executes Chrome. This works indeed. The common suggestion is however to do that on the shortcut that executes the browser. But that won’t cover the case when I run the browser from a shell. Something I do, every now and then. Don’t ask.

So a more sledge hammer solution is to edit the wrapper script:

$ which google-chrome
/usr/bin/google-chrome

So edit this file (as root), and change the last line from

exec -a "$0" "$HERE/chrome" "$@"

to

exec -a "$0" "$HERE/chrome" --simulate-outdated-no-au='Tue, 31 Dec 2099' "$@"

What does this mean, then? Well, according to the list of Google Chrome switches, this switch “simulates that current version is outdated and auto-update is off”. The date is referred to in the source’s upgrade_detector_impl.cc. Look there if you want to figure out why this works (I didn’t bother, actually).

Notes on Bluetooth on Linux internals

Introduction

These are notes I made while trying to make my Sony WH-CH510 bluetooth headphones work properly with my Linux Mint 19 machine. It’s evident that an upgrade of the whole OS would have fixed the problem, but I have my opinion on upgrades.

The problem: It takes a long time for the headphones to connect (around 20-30 seconds), and once that happens, the headphones are not automatically chosen by Pulseaudio as the output device. There are hacky solutions to the second part of the problems, but I have this thing about wanting to solve a problem properly.

The twist is that there’s no problem at all with Sony’s WH-CH500 headphones, neither with a pair of junky earbuds, which are labeled Y30.

So after trying quite a few quick fixes, I decided to get to the bottom of the problem. The good news is that I found out the reason for the problem. The bad news is that I didn’t find any direct solution for it.

So my solution was to upgrade the bluetooth daemon, and I did it in a rather exotic way: I basically installed a Linux Mint 21.1 (“Victoria”) pretty much in the same way as explained in this post. Now bluetoothd version 5.64 runs instead of Linux Mint’s 19 version 5.48 of this daemon, and everything works like a charm. But it’s a rather tangled solution if you don’t have this parallel Linux distribution installed for other reasons.

The rest of this post is a collection of things I tried before upgrading the daemon.

Bluetooth is handled by the kernel, which presents an hci device (typically hci0). The heavy lifting of implementing the protocol is done by bluetoothd ( /usr/lib/bluetooth/bluetoothd on my machine, started by the bluetooth systemd service). Try, for example,

$ hciconfig

Sniffing

To capture bluetooth communication, there are two primary option: The bluetooth0 interface in Wireshark or the btmon command line utility. Wireshark is more comprehensive as always, however btmon is actually easier to work with, because all crucial information is concentrated in a text file. The eternal tradeoff between GUI and text. Possibly, use both.

I’m going to show excerpts from btmon dumps below, obtained with e.g.

$ sudo stdbuf -oL btmon | tee btmon.txt

This could have been just “sudo btmon”, but using stdbuf and tee, there’s also data printed out to console in real time (stdbuf removes unnecessary buffering).

I skip a lot of entries, because there are, well, a lot of them. Hopefully I didn’t throw away anything relevant.

With btmon, “>” means incoming to host, and “<” means outgoing from host (the device is at the left side, which is a bit odd).

I’ve never carried out a bluetooth-related project, so all my comments on btmon’s output below are no more than hopefully intelligent guesses. I don’t pretend to be acquainted with any of the related protocols.

The connection

This is WH-CH510′s connection request (the earbud’s request was exactly the same):

> HCI Event: Connect Request (0x04) plen 10                #11 [hci0] 10.725859
        Address: 30:53:C1:11:40:2D (OUI 30-53-C1)
        Class: 0x240404
          Major class: Audio/Video (headset, speaker, stereo, video, vcr)
          Minor class: Wearable Headset Device
          Rendering (Printing, Speaker)
          Audio (Speaker, Microphone, Headset)
        Link type: ACL (0x01)
< HCI Command: Accept Connection R.. (0x01|0x0009) plen 7  #12 [hci0] 10.725914
        Address: 30:53:C1:11:40:2D (OUI 30-53-C1)
        Role: Master (0x00)

And after a few packet exchanges, this appears in the dump output (three times, not clear why):

@ MGMT Event: Device Connected (0x000b) plen 28       {0x0001} [hci0] 11.256871
        BR/EDR Address: 30:53:C1:11:40:2D (OUI 30-53-C1)
        Flags: 0x00000000
        Data length: 15
        Name (complete): WH-CH510
        Class: 0x240404
          Major class: Audio/Video (headset, speaker, stereo, video, vcr)
          Minor class: Wearable Headset Device
          Rendering (Printing, Speaker)
          Audio (Speaker, Microphone, Headset)

Cheap earbud’s service negotiation

Unlike USB, the device is in control: The requests information, and the host responds. The device chooses how to set up the connection, and the host follows suit. And it’s also the device that possibly messes up.

For the Y30 earbuds, the attribute request / response session went as follows.

First, the device checks if the host supports Handsfree Audio Gateway (0x111f), by asking for attributes, but the host doesn’t have any of it:

> ACL Data RX: Handle 17 flags 0x02 dlen 24                #42 [hci0] 14.317596
      Channel: 64 len 20 [PSM 1 mode 0] {chan 0}
      SDP: Service Search Attribute Request (0x06) tid 1 len 15
        Search pattern: [len 6]
          Sequence (6) with 3 bytes [16 extra bits] len 6
            UUID (3) with 2 bytes [0 extra bits] len 3
              Handsfree Audio Gateway (0x111f)
        Max record count: 512
        Attribute list: [len 6]
          Sequence (6) with 3 bytes [16 extra bits] len 6
            Unsigned Integer (1) with 2 bytes [0 extra bits] len 3
              0x0004
        Continuation state: 0
< ACL Data TX: Handle 17 flags 0x00 dlen 14                #43 [hci0] 14.317758
      Channel: 64 len 10 [PSM 1 mode 0] {chan 0}
      SDP: Service Search Attribute Response (0x07) tid 1 len 5
        Attribute bytes: 2
        Continuation state: 0

So the device tries AVDTP (0x0019) instead:

> ACL Data RX: Handle 17 flags 0x02 dlen 24                #45 [hci0] 14.322578
      Channel: 64 len 20 [PSM 1 mode 0] {chan 0}
      SDP: Service Search Attribute Request (0x06) tid 2 len 15
        Search pattern: [len 6]
          Sequence (6) with 3 bytes [16 extra bits] len 6
            UUID (3) with 2 bytes [0 extra bits] len 3
              AVDTP (0x0019)
        Max record count: 512
        Attribute list: [len 6]
          Sequence (6) with 3 bytes [16 extra bits] len 6
            Unsigned Integer (1) with 2 bytes [0 extra bits] len 3
              0x0004
        Continuation state: 0
< ACL Data TX: Handle 17 flags 0x00 dlen 60                #46 [hci0] 14.322737
      Channel: 64 len 56 [PSM 1 mode 0] {chan 0}
      SDP: Service Search Attribute Response (0x07) tid 2 len 51
        Attribute bytes: 48
          Attribute list: [len 21] {position 0}
            Attribute: Protocol Descriptor List (0x0004) [len 2]
              Sequence (6) with 6 bytes [8 extra bits] len 8
                UUID (3) with 2 bytes [0 extra bits] len 3
                  L2CAP (0x0100)
                Unsigned Integer (1) with 2 bytes [0 extra bits] len 3
                  0x0019
              Sequence (6) with 6 bytes [8 extra bits] len 8
                UUID (3) with 2 bytes [0 extra bits] len 3
                  AVDTP (0x0019)
                Unsigned Integer (1) with 2 bytes [0 extra bits] len 3
                  0x0103
          Attribute list: [len 21] {position 1}
            Attribute: Protocol Descriptor List (0x0004) [len 2]
              Sequence (6) with 6 bytes [8 extra bits] len 8
                UUID (3) with 2 bytes [0 extra bits] len 3
                  L2CAP (0x0100)
                Unsigned Integer (1) with 2 bytes [0 extra bits] len 3
                  0x0019
              Sequence (6) with 6 bytes [8 extra bits] len 8
                UUID (3) with 2 bytes [0 extra bits] len 3
                  AVDTP (0x0019)
                Unsigned Integer (1) with 2 bytes [0 extra bits] len 3
                  0x0103
        Continuation state: 0

And yes, the host supports it.

AVDTP is (according to Wikipedia) used by the advanced audio distribution (A2DP) profile to stream music to stereo headsets over an L2CAP channel intended for video distribution profile in the Bluetooth transmission.

So it goes on with connecting channel 65 to service number 0x0019 (PSM stands for Protocol Service Multiplexor).

> ACL Data RX: Handle 17 flags 0x02 dlen 12                #51 [hci0] 14.358888
      L2CAP: Connection Request (0x02) ident 3 len 4
        PSM: 25 (0x0019)
        Source CID: 65
< ACL Data TX: Handle 17 flags 0x00 dlen 16                #52 [hci0] 14.358945
      L2CAP: Connection Response (0x03) ident 3 len 8
        Destination CID: 65
        Source CID: 65
        Result: Connection pending (0x0001)
        Status: Authorization pending (0x0002)
< ACL Data TX: Handle 17 flags 0x00 dlen 16                #53 [hci0] 14.359202
      L2CAP: Connection Response (0x03) ident 3 len 8
        Destination CID: 65
        Source CID: 65
        Result: Connection successful (0x0000)
        Status: No further information available (0x0000)
< ACL Data TX: Handle 17 flags 0x00 dlen 12                #54 [hci0] 14.359220
      L2CAP: Configure Request (0x04) ident 3 len 4
        Destination CID: 65
        Flags: 0x0000
AVDTP (0x0019)> HCI Event: Number of Completed Packets (0x13) plen 5     #55 [hci0] 14.361709
        Num handles: 1
        Handle: 17
        Count: 1

This is followed by a discovery phase:

@ MGMT Command: Start Discovery (0x0023) plen 1       {0x0001} [hci0] 14.362330
        Address type: 0x07
          BR/EDR
          LE Public
          LE Random

In the packet exchange that follows, the device obtains the capabilities of the host, and the audio connection is set up.

Sony WH-CH510′s service negotiation

The WH-CH510 takes another approach: It issues a Service Search Request for the Headset AG (0x1112). AG means Audio Gateway.

> ACL Data RX: Handle 20 flags 0x02 dlen 17                #48 [hci0] 11.736388
      Channel: 64 len 13 [PSM 1 mode 0] {chan 0}
      SDP: Service Search Request (0x02) tid 1 len 8
        Search pattern: [len 5]
          Sequence (6) with 3 bytes [8 extra bits] len 5
            UUID (3) with 2 bytes [0 extra bits] len 3
              Headset AG (0x1112)
        Max record count: 68
        Continuation state: 0
< ACL Data TX: Handle 20 flags 0x00 dlen 18                #49 [hci0] 11.736611
      Channel: 64 len 14 [PSM 1 mode 0] {chan 0}
      SDP: Service Search Response (0x03) tid 1 len 9
        Total record count: 1
        Current record count: 1
        Record handle: 0x1000c
        Continuation state: 0

And yes, it’s supported and given the handle 0x1000c. Using this handle, the device asks for this service’s attributes:

> ACL Data RX: Handle 20 flags 0x02 dlen 23                #51 [hci0] 11.741392
      Channel: 64 len 19 [PSM 1 mode 0] {chan 0}
      SDP: Service Attribute Request (0x04) tid 2 len 14
        Record handle: 0x1000c
        Max attribute bytes: 277
        Attribute list: [len 7]
          Sequence (6) with 5 bytes [8 extra bits] len 7
            Unsigned Integer (1) with 4 bytes [0 extra bits] len 5
              0x0000ffff
        Continuation state: 0
< ACL Data TX: Handle 20 flags 0x00 dlen 97                #52 [hci0] 11.741610
      Channel: 64 len 93 [PSM 1 mode 0] {chan 0}
      SDP: Service Attribute Response (0x05) tid 2 len 88
        Attribute bytes: 85
          Attribute list: [len 83] {position 0}
            Attribute: Service Record Handle (0x0000) [len 2]
              0x0001000c
            Attribute: Service Class ID List (0x0001) [len 2]
              UUID (3) with 2 bytes [0 extra bits] len 3
                Headset AG (0x1112)
              UUID (3) with 2 bytes [0 extra bits] len 3
                Generic Audio (0x1203)
            Attribute: Protocol Descriptor List (0x0004) [len 2]
              Sequence (6) with 3 bytes [8 extra bits] len 5
                UUID (3) with 2 bytes [0 extra bits] len 3
                  L2CAP (0x0100)
              Sequence (6) with 5 bytes [8 extra bits] len 7
                UUID (3) with 2 bytes [0 extra bits] len 3
                  RFCOMM (0x0003)
                Unsigned Integer (1) with 1 byte [0 extra bits] len 2
                  0x0c
            Attribute: Browse Group List (0x0005) [len 2]
              UUID (3) with 2 bytes [0 extra bits] len 3
                Public Browse Root (0x1002)
            Attribute: Bluetooth Profile Descriptor List (0x0009) [len 2]
              Sequence (6) with 6 bytes [8 extra bits] len 8
                UUID (3) with 2 bytes [0 extra bits] len 3
                  Headset (0x1108)
                Unsigned Integer (1) with 2 bytes [0 extra bits] len 3
                  0x0102
            Attribute: Unknown (0x0100) [len 2]
              Headset Voice gateway [len 21]
        Continuation state: 0

The device chooses to connect channel 65 to the RFCOMM service:

> ACL Data RX: Handle 20 flags 0x02 dlen 12                #62 [hci0] 12.337691
      L2CAP: Connection Request (0x02) ident 6 len 4
        PSM: 3 (0x0003)
        Source CID: 65
< ACL Data TX: Handle 20 flags 0x00 dlen 16                #63 [hci0] 12.337747
      L2CAP: Connection Response (0x03) ident 6 len 8
        Destination CID: 64
        Source CID: 65
        Result: Connection successful (0x0000)
        Status: No further information available (0x0000)

After some configuration packets, the discovery begins:

@ MGMT Event: Discovering (0x0013) plen 2             {0x0001} [hci0] 14.686897
        Address type: 0x07
          BR/EDR
          LE Public
          LE Random
        Discovery: Disabled (0x00)
> ACL Data RX: Handle 20 flags 0x02 dlen 18                #91 [hci0] 15.848944
      Channel: 64 len 14 [PSM 3 mode 0] {chan 0}
      RFCOMM: Unnumbered Info with Header Check (UIH) (0xef)
         Address: 0x63 cr 1 dlci 0x18
         Control: 0xef poll/final 0
         Length: 10
         FCS: 0x0e
        41 54 2b 43 49 4e 44 3d 3f 0d 0e                 AT+CIND=?..
> ACL Data RX: Handle 20 flags 0x02 dlen 17                #92 [hci0] 18.849015
      Channel: 64 len 13 [PSM 3 mode 0] {chan 0}
      RFCOMM: Unnumbered Info with Header Check (UIH) (0xef)
         Address: 0x63 cr 1 dlci 0x18
         Control: 0xef poll/final 0
         Length: 9
         FCS: 0x0e
        41 54 2b 43 49 4e 44 3f 0d 0e                    AT+CIND?..

This discovery isn’t all that successful: The device sends AT commands, but the host doesn’t respond to them. 4 seconds of futile attempts.

After some useless back and forth, the device tries again with the same Service Search Request, to which it receives the same answer, and so it goes on.

> ACL Data RX: Handle 20 flags 0x02 dlen 17               #108 [hci0] 20.717682
      Channel: 65 len 13 [PSM 1 mode 0] {chan 1}
      SDP: Service Search Request (0x02) tid 3 len 8
        Search pattern: [len 5]
          Sequence (6) with 3 bytes [8 extra bits] len 5
            UUID (3) with 2 bytes [0 extra bits] len 3
              Headset AG (0x1112)
        Max record count: 68
        Continuation state: 0

[ ... ]

The device disconnects the futile channel 65:

> ACL Data RX: Handle 20 flags 0x02 dlen 12               #114 [hci0] 20.818859
      L2CAP: Disconnection Request (0x06) ident 10 len 4
        Destination CID: 65
        Source CID: 64
< ACL Data TX: Handle 20 flags 0x00 dlen 12               #115 [hci0] 20.818906
      L2CAP: Disconnection Response (0x07) ident 10 len 4
        Destination CID: 65
        Source CID: 64

And then it tries another few AT commands on this same channel, despite having disconnected it. It didn’t reconnect it, so probably disconnection doesn’t mean what I think it does…?

> ACL Data RX: Handle 20 flags 0x02 dlen 24               #118 [hci0] 22.225305
      Channel: 64 len 20 [PSM 3 mode 0] {chan 0}
      RFCOMM: Unnumbered Info with Header Check (UIH) (0xef)
         Address: 0x63 cr 1 dlci 0x18
         Control: 0xef poll/final 0
         Length: 16
         FCS: 0x0e
        41 54 2b 43 4d 45 52 3d 33 2c 30 2c 30 2c 31 0d  AT+CMER=3,0,0,1.
        0e                                               .
> ACL Data RX: Handle 20 flags 0x02 dlen 18               #119 [hci0] 25.285306
      Channel: 64 len 14 [PSM 3 mode 0] {chan 0}
      RFCOMM: Unnumbered Info with Header Check (UIH) (0xef)
         Address: 0x63 cr 1 dlci 0x18
         Control: 0xef poll/final 0
         Length: 10
         FCS: 0x0e
        41 54 2b 43 43 57 41 3d 31 0d 0e                 AT+CCWA=1..

Needless to say, this was futile as well.

And then, out of the blue, the device requests to connect to AVDTP by choosing the service at address 0x0019.

> ACL Data RX: Handle 20 flags 0x02 dlen 12               #125 [hci0] 29.875346
      L2CAP: Connection Request (0x02) ident 11 len 4
        PSM: 25 (0x0019)
        Source CID: 64
< ACL Data TX: Handle 20 flags 0x00 dlen 16               #126 [hci0] 29.875431
      L2CAP: Connection Response (0x03) ident 11 len 8
        Destination CID: 65
        Source CID: 64
        Result: Connection pending (0x0001)
        Status: Authorization pending (0x0002)
< ACL Data TX: Handle 20 flags 0x00 dlen 16               #128 [hci0] 29.875677
      L2CAP: Connection Response (0x03) ident 11 len 8
        Destination CID: 65
        Source CID: 64
        Result: Connection successful (0x0000)
        Status: No further information available (0x0000)

It’s not clear where the device got the idea to do this: As far as I can tell, the device wasn’t informed by the host about the existence of this service, at least not directly.

From this point, the negotiation goes well, and an audio device is set up. This allows selecting the headphones in the Sound Settings. Something that is done automatically with the old headphones and the junky earbuds.

So what is the problem? Maybe that the host doesn’t answer the AT commands. This is maybe solved in later versions of bluetoothd or Linux distributions in general. It’s quite possible that my distribution is too old for these newer headphones. Upgrade or perish.

Or go the other way: Downgrade. I suppose the solution would be to disable the Headset AG profile (0x1112), so that bluetoothd refuses to play ball when this is requested. This would speed up the fallback to A2DP, I hope, and possibly solve the problem.

I’ve tried hard to find a way to make bluetoothd refuse to the Headset AG profile, but in vain (so far?). sdptool has the option to disable a service, however it’s deprecated, and bluez 5 won’t talk with it. The updated method to tickle bluetoothd is through Dbus. Not sure if it has an API for turning off a service.

Unfortunately, I have no idea how to do this except for compiling bluetoothd from its sources and remove that option altogether. Actually, changing the UUID is enough to make it unusable.

I tried that, but it didn’t work all that well. More on that below.

Now to some extra stuff I randomly found out while working on this.

bluetootctl

This utility talks with bluetoothd through Dbus.

Doesn’t require root (when run from a terminal window on the computer’s desktop):

$ bluetoothctl
[NEW] Controller 9C:BB:CC:DD:EE:FF compname [default]
[NEW] Device 78:2E:D4:D9:62:C1 Y30
[NEW] Device 00:18:09:76:27:29 WH-CH500
[NEW] Device 30:53:C1:11:40:2D WH-CH510
Agent registered
[bluetooth]# show
Controller 9C:BB:CC:DD:EE:FF (public)
	Name: compname
	Alias: compname
	Class: 0x001c0104
	Powered: yes
	Discoverable: yes
	Pairable: yes
	UUID: Headset AG                (00001112-0000-1000-8000-00805f9b34fb)
	UUID: Generic Attribute Profile (00001801-0000-1000-8000-00805f9b34fb)
	UUID: A/V Remote Control        (0000110e-0000-1000-8000-00805f9b34fb)
	UUID: OBEX File Transfer        (00001106-0000-1000-8000-00805f9b34fb)
	UUID: Generic Access Profile    (00001800-0000-1000-8000-00805f9b34fb)
	UUID: OBEX Object Push          (00001105-0000-1000-8000-00805f9b34fb)
	UUID: PnP Information           (00001200-0000-1000-8000-00805f9b34fb)
	UUID: IrMC Sync                 (00001104-0000-1000-8000-00805f9b34fb)
	UUID: A/V Remote Control Target (0000110c-0000-1000-8000-00805f9b34fb)
	UUID: Audio Source              (0000110a-0000-1000-8000-00805f9b34fb)
	UUID: Audio Sink                (0000110b-0000-1000-8000-00805f9b34fb)
	UUID: Vendor specific           (00005005-0000-1000-8000-0002ee000001)
	UUID: Message Notification Se.. (00001133-0000-1000-8000-00805f9b34fb)
	UUID: Phonebook Access Server   (0000112f-0000-1000-8000-00805f9b34fb)
	UUID: Message Access Server     (00001132-0000-1000-8000-00805f9b34fb)
	UUID: Headset                   (00001108-0000-1000-8000-00805f9b34fb)
	Modalias: usb:v1D6Bp0246d0530
	Discovering: no

This utility spits out a lot of information by itself when the daemon is restarted with e.g. “systemctl restart bluetooth”. There’s also output when a device is connected and disconnected.

An interesting feature of bluetootctl is the submenus, in particular “gatt” and “advertise”. Maybe the former allows deregistering UUIDs.

Try

[bluetooth]# menu gatt

and when done, go back to original menu:

[bluetooth]# back

btmgmt

btmgmt talks with the kernel directly through an AF_BLUETOOTH raw network socket. I considered this tool because it has the rm-uuid command, which is supposed to remove a UUID.

$ sudo btmgmt
[mgmt]# rm-uuid 00001112-0000-1000-8000-00805f9b34fb
Remove UUID succeeded. Class 0x1c0104

This is reverted when the bluetooth service is restarted. But it doesn’t seem to have any effect on the interface anyhow. The UUID keeps appearing in bluetoothctl’s “show” and the service is advertised and used. “clr-uuids” apparently removes all UUIDs, but this has no real effect.

It seems like the effective UUIDs are kept in bluetoothd. btmgmt changes the UUIDs in the kernel. See “Remove UUID Command” in mgmt-api.txt.

btmgmt also gets very active when bluetoothd is restarted and other events occur.

Talking with bluetoothd directly through DBus

See my notes on DBus on this post. Getting a property:

$ dbus-send --system --dest=org.bluez --print-reply /org/bluez/hci0 org.freedesktop.DBus.Properties.Get string:org.bluez.Adapter1 string:Address
method return time=1685778877.065819 sender=:1.4 -> destination=:1.4934 serial=82 reply_serial=2
   variant       string "9C:BB:CC:DD:EE:FF"

Let’s break this down. Bluetoothd’ Dbus API is published in its source’s doc/ subdirectory. The Address property of the adapter is documented in adapter-api.txt. So:

  • –print-reply: We want the reply to this query, of course.
  • –system: Bluetoothd is connected to the system DBus.
  • –dest=org.bluez: Taken from “Service” in adapter-api.txt.
  • /org/bluez/hci0: Taken from “Object path” in adapter-api.txt.
  • org.freedesktop.DBus.Properties.Get: Every dbus-send command needs a method. In this case fetching a property’s value. So use the generic method for fetching a property.
  • string:org.bluez.Adapter1: Taken from “Interface” in adapter-api.txt.
  • string:Address: This is the name of the property, as listed in adapter-api.txt.

Likewise, I can fetch the UUIDs:

$ dbus-send --print-reply --system --dest=org.bluez /org/bluez/hci0 org.freedesktop.DBus.Properties.Get string:org.bluez.Adapter1 string:UUIDs
method return time=1685779625.693856 sender=:1.4 -> destination=:1.5017 serial=89 reply_serial=2
   variant       array [
         string "00001112-0000-1000-8000-00805f9b34fb"
         string "00001801-0000-1000-8000-00805f9b34fb"
         string "0000110e-0000-1000-8000-00805f9b34fb"
         string "00001106-0000-1000-8000-00805f9b34fb"
         string "00001800-0000-1000-8000-00805f9b34fb"
         string "00001105-0000-1000-8000-00805f9b34fb"
         string "00001200-0000-1000-8000-00805f9b34fb"
         string "0000110c-0000-1000-8000-00805f9b34fb"
         string "00001104-0000-1000-8000-00805f9b34fb"
         string "0000110a-0000-1000-8000-00805f9b34fb"
         string "0000110b-0000-1000-8000-00805f9b34fb"
         string "00005005-0000-1000-8000-0002ee000001"
         string "00001133-0000-1000-8000-00805f9b34fb"
         string "0000112f-0000-1000-8000-00805f9b34fb"
         string "00001132-0000-1000-8000-00805f9b34fb"
         string "00001108-0000-1000-8000-00805f9b34fb"
      ]

So this is how bluetoothctl got these values. Unfortunately, this property is read-only according to adapter-api.txt, so it can’t be manipulated with a Set method.

It’s of course possible to run methods that are published in bluetoothd’s DBus API, but I didn’t find anything related to disabling services.

Hacking the source

Download the sources for bluez 5.48-0ubuntu3.1 as bluez_5.48.orig.tar.xz (which is the version running on Mint 19).

In lib/sdp.h, change 0x1112 to 0xeb12. Same in lib/uuid.h and in src/profile.c.

Then in the source’s root directory, go:

$ ./configure && echo Success

and then just

$ make && echo Success

On my machine, there was a need to install libical, to make configure work, i.e.

$ sudo apt-get install libical-dev

And then replace /usr/lib/bluetooth/bluetoothd with the compiled version in src/. Keep a copy of the old executable, of course.

That didn’t work at all. The old UUID kept appearing in bluetoothctl’s output for “show”. There was a change, however: The WH-CH510 headphones refused to connect to the host, and reverted to pairing. At least I did something, I thought. But as it turned out, these headphones refused to connect to the host even after going back to the original bluetooth daemon (but had no problem with my cellphone). Y30 had no problems, as usual.

Resetting the headphone by pressing the power button and “-” button for 7 seconds didn’t help either. What eventually did the trick was to remove /usr/lib/bluetooth/bluetoothd, go “systemctl restart bluetooth”, which failed of course. Then return bluetoothd to its place, which worked, as expected. And then everything was back to normal again.

Extra reading

  • A Debian wiki page with several interesting examples (in particular how to use dbus-send to talk with bluetoothd)
  • This page contains a lot of information about using command line
  • The list of tools that come with the bluez package
  • Some information about configuration files.

Random jots

  • The bluetooth service is defined in /lib/systemd/system/bluetooth.service, which runs /usr/lib/bluetooth/bluetoothd.
  • It’s also possible to run the daemon directly, by typing “/usr/lib/bluetooth/bluetoothd” at shell prompt. The daemon runs in the foreground in this case. Add the “-n” flag to get the logging information on the console as well.
  • bluetoothd stores persistent information (the list and information about already discovered devices in particular) in /var/lib/bluetooth. This directory can be removed

It’s possible to stop the Bluetooth daemon with

# systemctl stop bluetooth

however clicking on desktop’s bluetooth applet restarts it automatically, unless it is running by other means (e.g. started manually with a command).

The “bluetoothctl” command won’t do this, but rather wait for a connection. It’s actually OK to turn off the bluetooth deamon while this utility is running.

After upgrading bluetoothd as mentioned above, I noticed a lot of log messages of this sort every 16 seconds or so:

kernel: Bluetooth: hci0: last event is not cmd complete (0x0f)

But looking at old logs, it’s evident that these existed in the past as well. So they’re not related to my manipulations with the Bluetooth daemon. In fact, these messages appear while the Cinnamon Bluetooth applet’s utility window is displayed. Close this window, and the messages stop. This is a kernel bug that was fixed in kernel v5.0.

Linux Mint + Cinnamon: Volume buttons stop to work suddenly

The nuisance

After trying to fix another problem with Pulseaudio, and messing up a bit with its configuration files, the option to control the volume by virtue of keyboard buttons suddenly stopped to work. The cursor would blink briefly when pressing the button, but nothing else happened.

I tried all the fairly normal things, including to restart the Pulseaudio daemon, to restart Cinnamon (with Alt-F2 + “r”), restart the session by changing the user (to the same user), disconnect and reconnect the (USB) keyboard, and a whole lot of other things.

It took me quite some time to fix this, so here’s what worked for me this time, along with some debug info.

The machine was a Linux Mint 19 with Cinnamon.

At an earlier stage, even the sound applet was gone from its desktop panel. To fix that, I right-clicked the panel, picked Troubleshoot > Looking Glass, and picked the Extension tab. There’s an applet listed called “Sound”. So I right-clicked it, and chose “Reload Code”. That got the applet back to the panel, and it worked flawlessly. But then I was stuck with the volume button problem.

The fix

What I actually did:

  • Kill the process named csd-keyboard (probably irrelevant)
  • Kill the process named csd-media-keys
  • Restart pulseaudio with “pulseaudio -k”

This was the output of journalctl as a result of these:

May 31 12:17:03 cinnamon-session[2115]: WARNING: t+1132491.55749s: Application 'cinnamon-settings-daemon-keyboard.desktop' killed by signal 15
May 31 12:17:17 cinnamon-session[2115]: WARNING: t+1132505.78238s: Application 'cinnamon-settings-daemon-media-keys.desktop' killed by signal 15
May 31 12:17:17 rtkit-daemon[2284]: Successfully made thread 4304 of process 4304 (n/a) owned by '1010' high priority at nice level -11.
May 31 12:17:17 rtkit-daemon[2284]: Supervising 8 threads of 4 processes of 1 users.
May 31 12:17:17 pulseaudio[4304]: [pulseaudio] pid.c: Daemon already running.
May 31 12:18:04 bluetoothd[12009]: Endpoint unregistered: sender=:1.120210 path=/MediaEndpoint/A2DPSource
May 31 12:18:04 bluetoothd[12009]: Endpoint unregistered: sender=:1.120210 path=/MediaEndpoint/A2DPSink
May 31 12:18:04 rtkit-daemon[2284]: Successfully made thread 4345 of process 4345 (n/a) owned by '1010' high priority at nice level -11.
May 31 12:18:04 rtkit-daemon[2284]: Supervising 4 threads of 4 processes of 1 users.
May 31 12:18:04 pulseaudio[4345]: [pulseaudio] sink.c: Default and alternate sample rates are the same.
May 31 12:18:04 rtkit-daemon[2284]: Supervising 3 threads of 3 processes of 1 users.
May 31 12:18:04 rtkit-daemon[2284]: Successfully made thread 4347 of process 4345 (n/a) owned by '1010' RT at priority 5.
May 31 12:18:04 rtkit-daemon[2284]: Supervising 4 threads of 3 processes of 1 users.
May 31 12:18:04 rtkit-daemon[2284]: Supervising 4 threads of 3 processes of 1 users.
May 31 12:18:04 rtkit-daemon[2284]: Successfully made thread 4348 of process 4345 (n/a) owned by '1010' RT at priority 5.
May 31 12:18:04 rtkit-daemon[2284]: Supervising 5 threads of 3 processes of 1 users.
May 31 12:18:04 rtkit-daemon[2284]: Supervising 5 threads of 3 processes of 1 users.
May 31 12:18:04 rtkit-daemon[2284]: Successfully made thread 4349 of process 4345 (n/a) owned by '1010' RT at priority 5.
May 31 12:18:04 rtkit-daemon[2284]: Supervising 6 threads of 3 processes of 1 users.
May 31 12:18:05 rtkit-daemon[2284]: Supervising 6 threads of 3 processes of 1 users.
May 31 12:18:05 rtkit-daemon[2284]: Successfully made thread 4350 of process 4345 (n/a) owned by '1010' RT at priority 5.
May 31 12:18:05 rtkit-daemon[2284]: Supervising 7 threads of 3 processes of 1 users.
May 31 12:18:05 bluetoothd[12009]: Endpoint registered: sender=:1.120482 path=/MediaEndpoint/A2DPSource
May 31 12:18:05 bluetoothd[12009]: Endpoint registered: sender=:1.120482 path=/MediaEndpoint/A2DPSink
May 31 12:18:05 pulseaudio[4345]: [pulseaudio] backend-ofono.c: Failed to register as a handsfree audio agent with ofono: org.freedesktop.DBus.Error.ServiceUnknown: The name org.ofono was not provided by any .service files
May 31 12:18:05 rtkit-daemon[2284]: Successfully made thread 4352 of process 4352 (n/a) owned by '1010' high priority at nice level -11.
May 31 12:18:05 rtkit-daemon[2284]: Supervising 8 threads of 4 processes of 1 users.
May 31 12:18:05 pulseaudio[4352]: [pulseaudio] pid.c: Daemon already running.
May 31 12:18:58 gnome-keyring-daemon[2204]: asked to register item /org/freedesktop/secrets/collection/login/9, but it's already registered

I suppose that killing csd-media-keys was the part that really did the trick, because that caused a request to start Pulseaudio.

Why it worked (presumably)

The cinnamon-settings-daemon is the component responsible for passing the keyboard request to Pulseaudio. Apparently, messing up with Pulseaudio caused one of its components, csd-media-keys, to mess up as well. Killing it caused cinnamon-settings-daemon to restart it automatically. From fresh.

It’s fine to kill the csd-* processes. Nothing dramatic happens. The killed process is just restarted. But I haven’t tried to kill cinnamon-settings-daemon itself. I believe it will restart Cinnamon completely, something I wanted to avoid.

Dbus activity

I’ve already written a post mentioning how to monitor the Dbus. So here’s a different take on the same topic.

The difference is quite evident when running dbus-monitor (not as root) as follows in order to monitor the activity for the current session:

$ dbus-monitor

This is the output as a result of pressing a volume up button, when it works correctly (i.e. after fixing the problem):

method call time=1685525392.173838 sender=:1.6531 -> destination=:1.6616 serial=1431 path=/org/cinnamon/SettingsDaemon/KeybindingHandler; interface=org.cinnamon.SettingsDaemon.KeybindingHandler; member=HandleKeybinding
   uint32 2
method call time=1685525392.174967 sender=:1.6616 -> destination=org.freedesktop.DBus serial=566 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=AddMatch
   string "type='signal',interface='ca.desrt.dconf.Writer',path='/ca/desrt/dconf/Writer/user',arg0path='/org/cinnamon/desktop/sound/'"
method return time=1685525392.175012 sender=org.freedesktop.DBus -> destination=:1.6616 serial=382 reply_serial=566
method call time=1685525392.175026 sender=:1.6616 -> destination=:1.6531 serial=567 path=/org/Cinnamon; interface=org.Cinnamon; member=ShowOSD
   array [
      dict entry(
         string "icon"
         variant             string "audio-volume-medium-symbolic"
      )
      dict entry(
         string "level"
         variant             int32 34
      )
   ]
method call time=1685525392.175170 sender=:1.6616 -> destination=org.freedesktop.DBus serial=568 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=RemoveMatch
   string "type='signal',interface='ca.desrt.dconf.Writer',path='/ca/desrt/dconf/Writer/user',arg0path='/org/cinnamon/desktop/sound/'"
method return time=1685525392.175189 sender=org.freedesktop.DBus -> destination=:1.6616 serial=383 reply_serial=568
method call time=1685525392.175198 sender=:1.6616 -> destination=org.freedesktop.DBus serial=569 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=AddMatch
   string "type='signal',interface='ca.desrt.dconf.Writer',path='/ca/desrt/dconf/Writer/user',arg0path='/org/cinnamon/desktop/sound/'"
method return time=1685525392.175216 sender=org.freedesktop.DBus -> destination=:1.6616 serial=384 reply_serial=569
method call time=1685525392.176330 sender=:1.6618 -> destination=org.freedesktop.DBus serial=26 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=RequestName
   string "org.freedesktop.ReserveDevice1.Audio2"
   uint32 5
signal time=1685525392.176383 sender=org.freedesktop.DBus -> destination=(null destination) serial=50 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
   string "org.freedesktop.ReserveDevice1.Audio2"
   string ""
   string ":1.6618"
signal time=1685525392.176411 sender=org.freedesktop.DBus -> destination=:1.6618 serial=51 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameAcquired
   string "org.freedesktop.ReserveDevice1.Audio2"
method return time=1685525392.176427 sender=org.freedesktop.DBus -> destination=:1.6618 serial=52 reply_serial=26
   uint32 1
method return time=1685525392.184853 sender=:1.6616 -> destination=:1.6531 serial=570 reply_serial=1431
method call time=1685525392.184915 sender=:1.6616 -> destination=org.freedesktop.DBus serial=571 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=RemoveMatch
   string "type='signal',interface='ca.desrt.dconf.Writer',path='/ca/desrt/dconf/Writer/user',arg0path='/org/cinnamon/desktop/sound/'"
method return time=1685525392.184937 sender=org.freedesktop.DBus -> destination=:1.6616 serial=385 reply_serial=571
method return time=1685525392.190757 sender=:1.6531 -> destination=:1.6616 serial=1432 reply_serial=567

Unfortunately, I didn’t save the output before the fix. But it was exactly two rows of output. As far as I recall, the first and last row from this dump were present when it didn’t work (i.e. the row involving KeybindingHandler’s request, and the return method that closed it).

The bus addresses can be listed with the following command:

$ busctl --user

In this specific session the output was:

NAME                                                       PID PROCESS         USER             CONNECTION    UNIT                      SESSION    DESCRIPTION
:1.0                                                      2103 systemd         eli              :1.0          user@1010.service         -          -
:1.1014                                                  45251 pxgsettings     eli              :1.1014       session-c1.scope          c1         -
:1.1015                                                  45277 scp-dbus-servic eli              :1.1015       user@1010.service         -          -
:1.1016                                                  45277 scp-dbus-servic eli              :1.1016       user@1010.service         -          -
:1.12                                                     2213 csd-a11y-keyboa eli              :1.12         session-c1.scope          c1         -
:1.1234                                                  53331 nemo            eli              :1.1234       session-c1.scope          c1         -
:1.13                                                     2221 csd-a11y-settin eli              :1.13         session-c1.scope          c1         -
:1.131                                                   16564 klauncher       eli              :1.131        session-c1.scope          c1         -
:1.16                                                     2232 csd-cursor      eli              :1.16         session-c1.scope          c1         -
:1.17                                                     2225 csd-color       eli              :1.17         session-c1.scope          c1         -
:1.18                                                     2238 csd-clipboard   eli              :1.18         session-c1.scope          c1         -
:1.19                                                     2242 csd-orientation eli              :1.19         session-c1.scope          c1         -
:1.20                                                     2233 csd-wacom       eli              :1.20         session-c1.scope          c1         -
:1.21                                                     2245 csd-xsettings   eli              :1.21         session-c1.scope          c1         -
:1.22                                                     2248 csd-mouse       eli              :1.22         session-c1.scope          c1         -
:1.24                                                     2256 csd-print-notif eli              :1.24         session-c1.scope          c1         -
:1.26                                                     2258 csd-background  eli              :1.26         session-c1.scope          c1         -
:1.27                                                     2260 gvfsd           eli              :1.27         user@1010.service         -          -
:1.28                                                     2267 csd-housekeepin eli              :1.28         session-c1.scope          c1         -
:1.29                                                     2274 csd-screensaver eli              :1.29         session-c1.scope          c1         -
:1.30                                                     2270 csd-power       eli              :1.30         session-c1.scope          c1         -
:1.31                                                     2299 dconf-service   eli              :1.31         user@1010.service         -          -
:1.32                                                     2285 csd-automount   eli              :1.32         session-c1.scope          c1         -
:1.329                                                   22590 xreader         eli              :1.329        session-c1.scope          c1         -
:1.33                                                     2306 gvfsd-fuse      eli              :1.33         user@1010.service         -          -
:1.330                                                   22596 xreaderd        eli              :1.330        user@1010.service         -          -
:1.332                                                   22606 WebKitNetworkPr eli              :1.332        session-c1.scope          c1         -
:1.35                                                     2313 csd-printer     eli              :1.35         session-c1.scope          c1         -
:1.37                                                     2349 gvfs-udisks2-vo eli              :1.37         user@1010.service         -          -
:1.38                                                     2384 gvfs-gphoto2-vo eli              :1.38         user@1010.service         -          -
:1.39                                                     2277 csd-xrandr      eli              :1.39         session-c1.scope          c1         -
:1.40                                                     2410 gvfs-goa-volume eli              :1.40         user@1010.service         -          -
:1.41                                                     2414 goa-daemon      eli              :1.41         user@1010.service         -          -
:1.42                                                     2427 goa-identity-se eli              :1.42         user@1010.service         -          -
:1.43                                                     2432 gvfs-mtp-volume eli              :1.43         user@1010.service         -          -
:1.44                                                     2436 gvfs-afc-volume eli              :1.44         user@1010.service         -          -
:1.448                                                   31116 gvfsd-http      eli              :1.448        user@1010.service         -          -
:1.457                                                   31367 gvfsd-network   eli              :1.457        user@1010.service         -          -
:1.46                                                     2472 polkit-gnome-au eli              :1.46         session-c1.scope          c1         -
:1.463                                                   31401 gvfsd-dnssd     eli              :1.463        user@1010.service         -          -
:1.47                                                     2481 cinnamon-killer eli              :1.47         session-c1.scope          c1         -
:1.48                                                     2478 nemo-desktop    eli              :1.48         session-c1.scope          c1         -
:1.49                                                     2480 nm-applet       eli              :1.49         session-c1.scope          c1         -
:1.5                                                      2115 cinnamon-sessio eli              :1.5          session-c1.scope          c1         -
:1.50                                                     2474 blueberry-obex- eli              :1.50         session-c1.scope          c1         -
:1.51                                                     2474 blueberry-obex- eli              :1.51         session-c1.scope          c1         -
:1.52                                                     2499 obexd           eli              :1.52         user@1010.service         -          -
:1.54                                                     2506 gvfsd-trash     eli              :1.54         user@1010.service         -          -
:1.55                                                     2512 gvfsd-metadata  eli              :1.55         user@1010.service         -          -
:1.56                                                     2535 python2         eli              :1.56         session-c1.scope          c1         -
:1.5653                                                  62813 chrome          eli              :1.5653       session-c1.scope          c1         -
:1.5654                                                  62813 chrome          eli              :1.5654       session-c1.scope          c1         -
:1.5655                                                  62813 chrome          eli              :1.5655       session-c1.scope          c1         -
:1.5656                                                  62813 chrome          eli              :1.5656       session-c1.scope          c1         -
:1.5661                                                  62813 chrome          eli              :1.5661       session-c1.scope          c1         -
:1.57                                                     2534 cinnamon-screen eli              :1.57         session-c1.scope          c1         -
:1.58                                                     2574 gnome-terminal  eli              :1.58         session-c1.scope          c1         -
:1.5834                                                  52878 xreader         eli              :1.5834       session-c1.scope          c1         -
:1.5836                                                  52891 WebKitNetworkPr eli              :1.5836       session-c1.scope          c1         -
:1.5842                                                  54509 xreader         eli              :1.5842       session-c1.scope          c1         -
:1.5843                                                  54522 WebKitNetworkPr eli              :1.5843       session-c1.scope          c1         -
:1.59                                                     2574 gnome-terminal  eli              :1.59         session-c1.scope          c1         -
:1.6                                                      2115 cinnamon-sessio eli              :1.6          session-c1.scope          c1         -
:1.60                                                     2579 gconfd-2        eli              :1.60         user@1010.service         -          -
:1.61                                                     2574 gnome-terminal  eli              :1.61         session-c1.scope          c1         -
:1.6105                                                  47745 xreader         eli              :1.6105       session-c1.scope          c1         -
:1.6107                                                  47757 WebKitNetworkPr eli              :1.6107       session-c1.scope          c1         -
:1.6477                                                  31538 thunderbird-bin eli              :1.6477       session-c1.scope          c1         -
:1.6478                                                  31538 thunderbird-bin eli              :1.6478       session-c1.scope          c1         -
:1.6531                                                   2451 cinnamon        eli              :1.6531       session-c1.scope          c1         -
:1.6562                                                  69100 csd-sound       eli              :1.6562       session-c1.scope          c1         -
:1.6592                                                   1641 firefox-bin     eli              :1.6592       session-c1.scope          c1         -
:1.6593                                                   1641 firefox-bin     eli              :1.6593       session-c1.scope          c1         -
:1.6594                                                   1700 Web Content     eli              :1.6594       session-c1.scope          c1         -
:1.6595                                                   1760 WebExtensions   eli              :1.6595       session-c1.scope          c1         -
:1.6596                                                   1824 Web Content     eli              :1.6596       session-c1.scope          c1         -
:1.6597                                                   1876 Web Content     eli              :1.6597       session-c1.scope          c1         -
:1.6598                                                   1975 cinnamon-settin eli              :1.6598       session-c1.scope          c1         -
:1.6599                                                   1975 cinnamon-settin eli              :1.6599       session-c1.scope          c1         -
:1.6608                                                   2640 Web Content     eli              :1.6608       session-c1.scope          c1         -
:1.6609                                                   3399 Web Content     eli              :1.6609       session-c1.scope          c1         -
:1.6615                                                   4286 csd-keyboard    eli              :1.6615       session-c1.scope          c1         -
:1.6616                                                   4296 csd-media-keys  eli              :1.6616       session-c1.scope          c1         -
:1.6617                                                   4296 csd-media-keys  eli              :1.6617       session-c1.scope          c1         -
:1.6618                                                   4345 pulseaudio      eli              :1.6618       session-c1.scope          c1         -
:1.6621                                                   4692 xed             eli              :1.6621       session-c1.scope          c1         -
:1.6625                                                   5225 busctl          eli              :1.6625       session-c1.scope          c1         -
:1.67                                                     2860 applet.py       eli              :1.67         session-c1.scope          c1         -
:1.7                                                      2189 at-spi-bus-laun eli              :1.7          user@1010.service         -          -
:1.73                                                     3537 gnome-system-mo eli              :1.73         session-c1.scope          c1         -
:1.8                                                      2196 at-spi2-registr eli              :1.8          user@1010.service         -          -
:1.9                                                      2204 gnome-keyring-d eli              :1.9          session-c1.scope          c1         -
:1.92                                                     8884 xdg-desktop-por eli              :1.92         user@1010.service         -          -
:1.93                                                     8888 xdg-document-po eli              :1.93         user@1010.service         -          -
:1.94                                                     8891 xdg-permission- eli              :1.94         user@1010.service         -          -
:1.95                                                     8902 pxgsettings     eli              :1.95         user@1010.service         -          -
:1.96                                                     8906 xdg-desktop-por eli              :1.96         user@1010.service         -          -
ca.desrt.dconf                                            2299 dconf-service   eli              :1.31         user@1010.service         -          -
ca.desrt.dconf-editor                                        - -               -                (activatable) -                         -
org.Cinnamon                                              2451 cinnamon        eli              :1.6531       session-c1.scope          c1         -
org.Cinnamon.HotplugSniffer                                  - -               -                (activatable) -                         -
org.Cinnamon.LookingGlass                                 2451 cinnamon        eli              :1.6531       session-c1.scope          c1         -
org.Cinnamon.Melange                                         - -               -                (activatable) -                         -
org.Cinnamon.Slideshow                                       - -               -                (activatable) -                         -
org.Nemo                                                 53331 nemo            eli              :1.1234       session-c1.scope          c1         -
org.NemoDesktop                                           2478 nemo-desktop    eli              :1.48         session-c1.scope          c1         -
org.PulseAudio1                                           4345 pulseaudio      eli              :1.6618       session-c1.scope          c1         -
org.a11y.Bus                                              2189 at-spi-bus-laun eli              :1.7          user@1010.service         -          -
org.bluez.obex                                            2499 obexd           eli              :1.52         user@1010.service         -          -
org.cinnamon.ScreenSaver                                  2534 cinnamon-screen eli              :1.57         session-c1.scope          c1         -
org.cinnamon.SettingsDaemon.KeybindingHandler             4296 csd-media-keys  eli              :1.6616       session-c1.scope          c1         -

So it’s quite clear that the players here were cinnamon’s main socket, csd-media-keys and pulseaudio.

Random insights on lead-acid battery theory

Overview

This is a collection of insights regarding lead-acid batteries, in particular those sealed batteries that are used in UPSes. Had it not been for my failed attempts to get a decent battery for my UPS, none of this would have been written. It was only when I asked myself why the UPS doesn’t maintain power nearly as long as I expected that I started to learn more about these batteries.

Batteries is far away from anything I do for a living. This is definitely not my expertise. Please keep that in mind. But as it turns out, there’s a lot to know about them.

Well, I think I’ll take that back: After a lot of playing with these batteries, my conclusion is that knowledge doesn’t help much. Run a test, see how long the battery holds up your computer, and that’s it. There doesn’t seem to be anything smarter to do.

There’s probably only one important thing to know about them: They should be fresh. That’s hardly new, and yet, that’s probably the bottom line. Lead-acid batteries discharge by themselves over time, and when they reach a certain level of discharge, they get damaged. Also, the discharge rate depends a lot on temperature. So a battery that has been stored in a hot place somewhere in a distant country for over a year is probably no good candidate for your UPS. The manufacturer’s timestamp is everything: It starts to seem to me that most batteries were more or less the same on the day that they left the factory. The difference is how much damage they caught during storage.

For a concise technical background, I recommend reading Power Sonic’s Technical Manual.

So without further ado, let’s go through my findings, in more or less random order.

A 7AH battery doesn’t really give 7AH

With lead-acid batteries, 7AH doesn’t meas 7A for 1 hour. Or 3.5A for 2 hours. Or any other combination, except for 0.35A for 20 hours. More about that below.

The amount of charge (and energy) that a lead-acid battery supplies until it’s discharged depends dramatically on the discharging current. The capacity printed on the battery is given for a 20-hours discharge, or using the jargon, 0.05C. That “C” is 7 taken from the 7AH figure, so 7AH are obtained if the discharge current is 0.35A. For larger currents, expect much less energy out of the battery.

This phenomenon is approximated by Peukert’s Law.

For example, my specific case: The load is 70W (at 142VA) according to the UPS itself. I’ll assume that the low power factor thing can be ignored, i.e. that the fact that the VA figure is twice the consumed power makes no difference. This low power factor is natural to switching power supplies, as they draw more current when the voltage is low, so their behavior is far from a plain resistor (unless specifically compensated to mitigate this effect). I’ll also assume that the UPS is 100% efficient on its voltage conversion, which is complete rubbish, but for the heck of it.

So for two 12V batteries in series it goes 70W/24V =~ 2.9A, which is about 0.4C (2.9 / 7 =~ 0.4). A ballpark figure can be taken from Figure 4 in Power Sonic’s Technical Manual, showing that the voltage starts to drop after about an hour, and reaches the critical value somewhere after an hour and a half. Note that I have different batteries.

Also from Table 2 of the same Manual, we have that the actual capacity of a 7AH battery, when drained with a 4.34A current, is 4.34AH (one hour). The current is higher than 2.9A, but given that the UPS isn’t really 100% efficient, it’s likely that the real discharge current is closer to 4A than to 2.9A. So that explains why the UPS said 1:12 hours when I updated the battery replacement date.

Many battery manufacturers supply datasheets with Discharge Characteristics Curves. Even better, if there are tables with Constant Current Discharge Characteristics (also referred to as F.V / Time specification). See Ritar’s datasheet for RT1270, for example. The numbers inside this table are the constant currents for each discharging scenario. Each row is the final voltage (F.V) per cell that is reached in this scenario, and each column represents the time it takes to reach this voltage.

It’s not clear at which voltage the UPS decides to stop discharging. Even though 1.60V per cell seems to be a recurring number in datasheets for the game over.  And on the other hand, I’ve repeatedly seen 0.35A (i.e. 0.05C) paired with 1.75V and 20 hours discharge in those F.V / Time tables. So it’s not really clear. Anyhow, finding a number that is similar to the intended current in the table can give an idea on how long the battery is supposed to last.

Obviously, different batteries behave differently on higher currents. I couldn’t find data on my “Bulls Power” batteries. So maybe they could meet the 7AH specification for a 20-hours discharge, and then perform really poorly with higher, real-life currents. No way to know for sure.

So what is the state of the battery after it has been discharged with less than 7AH? It’s still charged, as a matter of fact. A rapid discharge, which yields less than the full capacity is healthy for the battery. It’s when the full capacity is utilized with a slow discharge pattern that the battery can be damaged if it stays in that state for a long while.

Charging a lead-acid battery

There are in fact several ways to charge a lead acid battery (for example, this), but the common way to charge a battery is to feed it with a current of 0.3C (2.1A for a 7AH battery) until the voltage rises to above a threshold. Or to set a constant voltage (with a current limit) and charge until the current goes below a certain level. Then comes the second phase, which is the slow charging to 100%.

When the battery is full, a floating voltage should be applied to the battery. Each battery specifies its own preferred floating voltage, but they all land at around 13.5-13.8V. This is the correct way to maintain a fully charged battery: A small charging current compensates for the battery’s inherent discharge (typically around 0.001C, i.e. 7 mA for a 7AH battery), and the battery remains fully charged in a way that is best for its health.

Battery manufacturers usually state something like 10% discharge for 90 days or so. This corresponds to about 0.000046C, or ~0.3 mA for a 7AH battery. But in this scenario, the battery discharges against its own voltage, and not the elevated floating voltage (does it matter?).

Knowing the battery’s charge level

How does one estimate how much energy a lead-acid battery has? The answer is unpleasant, yet simple: There is really no way to measure it from the battery electronically. After reading quite some material on the subject, that became evident to me: There are plenty of papers describing exotic algorithms for estimating a battery’s health and charge level, and their abundance and variety proves that there’s really no way to tell, except for draining it.

Maybe the first question should have been: What is consumed when the battery gets discharged? For one, sulfuric acid reacts with the lead plates and become lead sulfate. When there’s no acid left, the battery is done. On the other hand, the lead plates themselves might deteriorate in the process. This can happen relatively early if the lead plates are partly damaged because of previous use (or abuse).

There is one way to measure the charge level that is considered reliable, which is measuring the open circuit voltage (OCV) after the battery has been disconnected for a while (some say a few hours, battery manufacturers typically require 24 hours). Letting the battery rest allows it to reach a chemical equilibrium, at which point the voltage reflects its charge level. This is surely true for a fresh battery, because the OCV reflects the specific gravity of the electrolyte, that is the concentration of the sulfuric acid.

As for batteries with some history, the picture is less clear, and I haven’t managed to figure out if the OCV voltages remain the same, and if the voltage vs. charge percentage relate to the original charge capacity, or the one that is available after the battery is worn out. The OCV measurementt covers the charge level in the sense of how much acid there’s left to consume, but will the lead plates hold that long?

For example, Power Sonic claims that the OVC goes from 1.94V/cell to 2.16V/cell for 0% to 100% charge respectively. As a 12-volt battery has 6 cells, this corresponds to 11.64V to 12.96V. These figures are quite similar to those presented by another manufacturer.

But what does 100% charge mean? 7AH or as much as is left when the battery has worked for some time? My anecdotal measurement of the batteries I took out from the UPS was 12.99V after letting them rest. In other words, they presented a OCV voltage corresponding to 100% charge, even though they had much less than 7AH.

So how does a UPS estimate the remaining runtime? Well, the simple way is to let the battery run out once, and there you have a number. Clearly, Smart UPS uses this method.

Are there any alternatives? In theory, the UPS could let the battery rest for 24 hours, and measure its OCV. This is possible, because most of the time the UPS doesn’t need the battery. But even my anecdotal measurement shows that a 100% charge-like reading doesn’t mean much.

For other types of batteries (Li-ion in particular), measuring the current on the battery, in and out (Coulomb Counting), gives an idea on how much charge it contains. This doesn’t work with lead acid batteries, because the recommended way to maintain a standby battery, is to continuously float charge it. That means holding a constant voltage (say, 2.25V per cell, that is 13.5V for a 12V battery, or 27V on a battery pair, as in SmartUPS 750).

As this voltage is higher than the OCV at rest, this causes a small trickle current (said to be about 0.001C), which compensates for the battery’s self discharge. Even if it overcharges the battery slightly, the gases that are released are recycled internally in a sealed battery, so there’s no damage.

Hence the recommended strategy for charging a lead-acid battery is to charge it quickly as long as its voltage / current pair indicates that it’s far from being fully charged, and then apply a constant, known and safe voltage. This allows it to charge completely slowly, and then maintain the charge without any risk for overcharging. Odds are that this is what the UPS does.

But that makes Coulomb Counting impossible: During the float charge phase (that is, virtually all the time) the current may and may not actually charge the battery.

Measuring the discharging curve

Being quite frustrated by bad batteries, I decided to go for a more direct approach: Instead of taking my computer down and pushing the battery into the UPS each time, I thought it would be easier and more informative to run a discharging test: I used my old Mustek 600 UPS to charge the battery, and then discharged it through a (cheap) 55W light bulb for a car’s headlight (which is intended for 12V of course). With this, I ran a classic lab experiment, recording voltage and current as a function of time. Like a school lab.

The first step is to charge the battery of course. I’ve discussed this topic briefly above, but what about my Mustek’s UPS? It takes a very easy and slow approach: With a partly discharged battery, it starts with an initial charging current of 0.4–0.35 A. This current goes slowly down as the battery’s voltage rises. The voltage goes up very slowly from 12.8V and eventually stabilizes at a voltage around 13.5-13.6V (depends on the battery). Charging a battery to a decent level takes 7 hours, but I went for a 24 hours charge before running a discharging test. Just to make sure the battery was really fully charged.

By the way, the Mustek UPS charges even when not powered on (but connected to power). When disconnected from power, no charging occurs.

Now to the interesting part: The discharging of the batteries. I made several tests, and they all yielded the same results, more or less. In all of these, I made accurate voltage measurements (with a Fluke) as a function of time. This is the plot of the last experiment I did, with a logarithmic x-axis, each ‘x’ mark on the plot is a measurement:

Discharging a lead acid battery at 0.55C, voltage vs. time

This experiment was done on one of the Bulls Power batteries.

I measured the current throughout the session: The light bulb drew 4.00 A in the beginning (corresponding to ~48W), and the currents remained above 3.8A during the first 20 minutes. So this can be considered a 0.55C discharge.

The first thing to note is that the graph fits the discharge curve for Ritar’s RT1270 for 0.55C during the first 18-19 minutes: The voltage goes down gradually, and drops about 0.04V/cell during the first 10 minutes. On the next 8-9 minutes, the voltage drop is about 0.05V/cell, also following Ritar’s curve.

But then it’s quickly downhill, strongly diverting from the expected graph. The battery collapses quickly at this point. I haven’t found a single reference to this behavior, but I suppose that it’s a result of aging. And/or deep discharge during storage.

Is this consistent with the fact that this battery held for 9 minutes in the UPS, along with one that behaves roughly the same? Maybe. The UPS reported a power consumption of 105W in that situation, so if I’ll assume 90% power efficiency, we have a current of 105 * (1 / 0.9) / 24 = 4.86A ≈ 0.7C. That’s somewhere between the graph for 0.55C and 1C. So with the steeper discharging curve of this case, it’s actually possible that the collapse began much earlier.

Other random takeaways:

  • With this battery, it doesn’t matter so much at which voltage the UPS powers itself off. The last part’s slope is so steep, so it’s a matter of 30 seconds this way or another.
  • A 55W light bulb is blinding and heating. Be sure to have it fixed in a way that prevents it from heating the battery and also make sure  that it’s literally out of sight, and that no visual contact will be needed with it as long as the experiment runs.
  • Check the crocodiles’ or easy-hook’s resistance. In particular crocodiles can have a high an unstable resistance (0.1Ω is high in this context, because it causes a voltage drop of 0.4V).
  • As it says in many information sources, lead batteries recover after a discharging session after some time of rest: After a day, I connected the battery to the bulb, and it began discharging at 11.8V, and falling rapidly.

Discharging curves, round #2

The saga went on, and I tell it in detail in the other post. The quick summary is: Being unhappy with the Bull batteries, I bought a pair of batteries from a company named Afik, and put them in the UPS. The results weren’t really impressing with these either, so I decided to replace the Afik batteries with something else. Eventually, I ended up with a pair of Vega Power batteries.

Unfortunately, I didn’t make any measurements on the Afik batteries before putting them in the UPS, mainly because I thought they would work, and end of story. So as things turned out, I obtained the discharging curve from the new Vega Power batteries before putting them in the UPS, and then I did the same thing with the Afik batteries only after they had been in the UPS for a few months.

This time I created an automatic test setting that allowed two readings per second, so the curves are more accurate and detailed.

Note to self: See new-computer/ups/lead acid batteries/discharge-tests-2/.

I used the same light 55W light bulb, which drew 4.0A at the beginning of the discharging test, and then went down slowly to about 3.5A towards the end of the test. More or less constant current, that is.

The colors of the curves in the graphs below represent which test they belong to:

  • Red: Vega Power battery #1.
  • Blue: Vega Power battery #2, first test.
  • Magenta: Vega Power battery #2, second test.
  • Green: Afik battery #1.
  • Cyan: Afik battery #2.

Evidently, I obtained a curve from Vega Power battery #2 twice: Once after charging for ~24 hours (from as it came from the shop) with the Mustek UPS, and the second time after a total of ~48 hours from the state of the previous discharging session. The graphs below might imply that I got these two measurements swapped, but no, there’s no mistake about this.

Vega Power battery #1 was charged during 26 hours (from its initial state from the shop), and then 18 hours with a brief pause between the two charging sessions.

So to the first graph. Time in minutes on the X axis, and voltage per cell on the Y axis.

Discharge curves of lead-acid batteries, linear time scale

The curves begin one minute after discharging starts, and stop when the battery reached 10.0V (with 6 cells in the battery, that’s 1.67V / cell). I’ll show more details below about the first minute. As for choosing 1.67V as the end for discharging: The graphs for charging current around 0.55C often go this low in datasheets, so I suppose this shouldn’t damage the battery.

The first and obvious thing one can see is that the Afik batteries held shorter than the Vega Power batteries: 55 minutes vs. 80-87 minutes. That’s consistent with the fact that the Vega Power lasted longer in the UPS.

But as I’ve written in that other post, the UPS started to panic-beeping after 7:30 minutes with the Afik batteries, and then kept power up for another 15 minutes. Why did that happen? There’s nothing in the green nor cyan curves that offers a clue for the reason to the early panic. On the other hand, it’s evident that these batteries lost voltage quite rapidly after about 40 minutes, possibly going into “deep discharge”. That said, they didn’t collapse nearly as quickly as the Bull Power batteries. So there are definitely different levels of junk.

As for the Vega Power batteries, they performed surprisingly well on these tests. The shortest run was 80 minutes. Taking a gross average of 3.75A as the current, that means that the battery gave 5AH. Quite impressive. Also, according to Ritar’s datasheet for RT1270, that battery will reach 1.85V/cell after one hour if a current of 3.321A is drawn from it. Vega Power got to that region after 70 minutes with a higher current.

So the question is why the UPS started panicking after 28 minutes and cut the power very soon after that. Indeed, the current that is drawn from the batteries was higher inside the UPS. But why that sudden cut? Does it have to do with the curves’ bending at around 1.96V?

In fact, the reason that I repeated the first discharging test on Vega Power #2 (in blue) was that sharp bend. To my surprise, the bend went away on the second test (in magenta), but the battery reached the 1.67V point 7 minutes earlier (after a 48 hours charging). Why? Don’t know. Lead acid batteries are not supposed to have any memory.

In the next graph, I’ve removed the curves for the Afik batteries, and left only Vega Power’s curves. In addition, I’ve shifted the positions of these curves in the X axis. Namely, I delayed Vega #1′s curve by 9 minutes, and Vega #2′s first test’s curve 2:15 minutes. And we get this:

Discharge curves of lead-acid batteries, aligned, linear time scale

So it’s evident that both batteries ran according to an accurate discharging pattern for at least 45 minutes, and then things happened. Is this the start of “deep discharge”? Does this mean that discharging the batteries below 1.95V is a bad idea? Maybe this is what my UPS thought, and accordingly stopped after 28 minutes (which could be the same point, as it probably drew more current than this test).

Doesn’t the part where all three curves overlap look a little linear? I’ll come back to that below.

It also looks like the shifting I made in the X axis compensates for differences in the initial charging level. If that’s true, the charging levels of Vega Power #2 were nearly the same in both tests (slightly more charge after the second, 48-hours, charging session). But if so, why did this battery reach 1.67V faster on the second round?

And why was Vega Power #1 significantly less charged after a super-long charging session? Maybe an issue with the Mustek UPS?

The third graph is the same as the first, but with logarithmic X-axis.

Discharge curves of lead-acid batteries, logarithmic time scale

The interesting thing about this representation is that it’s comparable with the curves that appear in some batteries’ datasheets. It’s quite evident that these curves are similar to those that are usually given for 0.55C.

The bends of the blue and red curves are more evident on this graph. Recall that they were obtained during the first tests of each of the Vega Power batteries. The pretty curve in magenta is the second run of Vega Power #2.

Finally, I discharged Afik battery #2 down to 1V, which is considered a damaging thing to do. But who cares, I have no plans for this battery anyhow. So here’s the curve:

Discharge curves of a lead-acid battery, including deep discharge

Note that this is the same test and same curve as shown above, only that I display it in full here.

Transient responses

So far I’ve been looking at the curves during the actual discharging phase. But some possibly interesting things happen before and after that.

So first, what happens when the discharging begins:

Discharge curves of lead-acid batteries, initial response

Surprise, surprise, there’s an undershoot. Why? I’m tired of trying to even speculate. But it’s definitely a thing. And by the way, the initial voltages (i.e. with zero current) have no meaning in particular (?), because the batteries didn’t have enough time to stabilize after charging.

Note that the X-axis is given in seconds here. Not minutes.

And here’s a close-up on the same graph, just to make the point that the undershoot occurred on all curves:

Discharge curves of lead-acid batteries, initial response, zoomed in

The next thing to look at is what happens when the discharging process is stopped. I did this by disconnecting the light bulb, so the current went down abruptly from 3.5A to zero. This occurs at time zero of the following graph.

Recovery from discharging of lead-acid batteries

Recall that Afik #2 (cyan) went down as low as 1V/cell, and yet it recovered quite similarly Afik #1, which didn’t go through this minor trauma.

It’s a well-known fact that lead-acid batteries recover after a high-current discharge and resume their capability to provide energy, even if they aren’t charged inbetween. This graph shows this phenomenon.

It’s worth looking at the first couple of minutes of the recovery. This is just a zoom-in of the previous graph (and with time axis shown in seconds instead).

Recovery from discharging of lead-acid batteries, zoomed in

Aside from the immediate jump of the voltage when the light bulb is disconnected, there’s a smooth and yet fast rise in the voltage.

Another thing that is evident from this graph, is how much faster the Afik batteries went down towards the 1.67V level, compared with the Vega Power batteries (this refers to the time period before zero).

Is a DC test legit?

This test is made with a DC current, but the UPS discharges the battery with an alternating current: As the UPS feeds the computer with an AC voltage, the delivered power as a function of time is a more or less a sinus function (if the UPS produces a sinus wave). At any time, the energy that is delivered to the computer is drawn from the battery. The UPS barely stores any energy in its own circuits. So the current from the battery is also a sinus, more or less.

So does a test with a DC current reflect the situation with an alternating current? Is it good enough to rely on the average power, and derive a DC current from that? According to Okazaki et al. (“Influence of superimposed alternating current on capacity and cycle life for lead-acid batteries“) the rippled current doesn’t change the battery’s capacity at all. They tested a current of I=I0(1+sinωt) at 0.1Hz to 4 kHz and found only negligible differences (1%). So the DC current test seems to be accurate.

Linear discharge curve?

I’m going back to Vega Power’s second graphs, where I aligned three graphs by shifting them in the X axis. Let’s look at this graph again, but now with a dash-dotted line which represents the first-order linear regression of the segment between 20 and 40 minutes:

Discharge curves of lead-acid batteries, linear segment shown

So there’s no doubt that the Vega Power batteries’ voltage went down linearly as a function of time for a while. Maybe it was the divergence from this linear descent that made the UPS panic after 28 minutes (once again, the UPS drew a higher current).

Looking at Afik’s curves, they don’t appear linear at any stage. Maybe that’s why the UPS became nervous very soon, but then nothing dramatic happened, so it kept running.

What about the Bulls Power battery? I didn’t show the graph with linear time scale above, but here it is:

Discharge curves of lead-acid batteries, linear segment shown

Once again, the linear regression is shown with a dash-dotted line. There are fewer measurement points, but it’s quite clear that the voltage descends linearly for a while.

The slopes of these dash-dotted lines are -2.09 mV/minute for the Vega Power batteries, and -2.86 mV/minute for Bulls Power.

What’s the explanation for this linear behavior? Reiterating that lead-acid batteries is not my expertise, I’ll give it a shot:

At the first stage of discharging, the voltage curves seem to be governed mainly by the concentration of sulfuric acid close to the lead plates. As the acid is consumed by the discharging process, the supply of new acid depends on motion of ions between the two plates. A high current means a quick rate of consumption that works against the motion of ions, some of which depends on plain diffusion. So the result is a lower concentration of acid, hence a lower voltage. This, I suppose, explains why the curves go down faster for higher currents, and why the battery recovers quickly afterwards.

But here’s the thing: When the current is constant, the gradient of the sulfuric acid’s concentration stabilizes inside the cell after a few minutes. The motion of ions gets into a stable pace. However, as the current flows, sulfuric acid is consumed. This brings down the concentration of acid overall, even though the differences (gradients) remain the same. The current is constant, and the sulfuric acid is consumed against electrical charge that passes through the battery, so we have a linear slope.

At some point, the curve breaks off from this pattern, and begins diving faster. A possible reason is that the lead plates begin to lose effective surface area (blocked by lead sulfate?), so the current needs to go through a smaller surface. This is equivalent to a larger current, with the due implications on voltage drop.

This seems to be what is often referred to as “deep discharge”. This is a term that is loosely used with reference to drawing too much charge from a battery. Everyone seems to agree that this phase reduces the battery’s capacity on the following cycles, but when does it start? Is it when the curve diverges from the linear pattern? Or when the voltage gets to the level that the manufacturer suggests avoiding?

Academic material on the topic is also scarce (for example, this paper), but it seems like this phase occurs when the lead plates start to take their impact. As evident from the graphs shown above, this phase is rather unpredictable. Even though lead-acid batteries are said not to have a memory effect, that seems to be true until it comes to the lead plates themselves. They remember.

It looks like Smart UPS takes the linear slope approach. Or maybe it looks at the slope of the voltage as a function of time. As long as sulfuric acid is consumed, it’s OK, but when the lead plates begin to deteriorate, that’s time to beep like crazy. This strategy makes a lot of sense for a long battery life, but less beneficial when power outages are rare, so who cares if the battery gets a small hit every few months. But all this is my speculation on how the UPS makes its choices.

Afterthoughts

So what have I learned from all this messing around with the batteries? Not a whole lot of relevant information, I’m afraid. Invented in 1859, lead-acid batteries are easy to manufacture and easy to use, but there doesn’t seem to be a simple theory that accurately describes their behavior. As my own anecdotal experiments show, even the same battery won’t repeat its own discharging curve twice.

Maybe it was because I tried low-quality batteries (or are they?) and inaccurate apparatus for charging the batteries (the Mustek UPS). On the other hand, it’s difficult to find written material that describes the behavior of these batteries, even under lab conditions.

The state of car batteries is often tested by measuring the “cranking current”. This is the huge current when the car is started. This is a crude and indirect measurement of the lead plates’ resistance, which I suppose gives some indication of the battery’s condition. Does it ensure that your battery will hold for the next 12 months? Good luck with that.

Startup idea

The main conclusion from all this rambling is that the only way to know how long a battery will supply power is to fully discharge it. That is, down to a reasonable level that doesn’t harm it. On the other hand, a UPS should be able to give an accurate estimate of how long time it can hold up the computer, so that its user can decide when it’s time to replace the battery or batteries. Plus, the UPS needs to know this for the purpose of shutting down the computer gently a few minutes before it’s game over.

Smart UPS has a feature called “calibration” which does exactly that: It puts the computer on the batteries and discharges them until they reach the lowest acceptable level, and then resumes normal operation. The problem is that if the main power goes out at that moment, there’s nothing to hold up the computer with. So this has to be initiated by the user every now and then.

Solution: Make a UPS with say, four batteries, each of which is connected independently to the UPS’ power conversion circuitry. This way, the UPS can initiate a full discharge test on one of these batteries while the others remain fully charged. At the worst moment, the overall capacity will stand at 75%.

These discharge tests can be initiated automatically by the UPS for each of the four batteries every couple of weeks or so. This way, the UPS can give an accurate number for how long the UPS will hold up power.

This allows the user to decide when it’s time to replace the batteries. It also makes it possible to replace the batteries gradually, without turning off power. And the UPS can also inform the user if the new battery was worth the money.

Will this startup work? I doubt it. The vast majority of people just buy a UPS and believe it will do the work. They realize their mistake when the power goes out for more than two minutes, and buy a new UPS instead. Replacing lead-acid batteries separately? Come on.