Posts

Jan 17, 2025

Modern event logs in OpenBMC (part 2)

This is part 2 in a series of updates on event logs; see part 1.

Current Status

In the last part I gave the following upcoming work items:

Allow-list / Block-list support in phosphor-logging.

Changing AdditionalData to be a dictionary. (done)

Generation of the Redfish Message Registry. (done)

Translation in bmcweb of phosphor-logging events to proper Redfish LogEntry format, including populating MessageArgs.

Adding ‘Hint’ support in Logging.Create.

AdditionalData

The Logging.Entry’s AdditionalData field has been migrated to be a dictionary.

A sample of a busctl introspect shows the new type:
xyz.openbmc_project.Logging.Entry           interface -         -                                                                                                                                                                                                                                                                                                                  -
.GetEntry                                   method    -         h                                                                                                                                                                                                                                                                                                                  -
.AdditionalData                             property  a{ss}     8 "READING_VALUE" "98.6" "SENSOR_NAME" "Inlet Temperature" "THRESHOLD_VALUE" "40.0" "UNITS" "xyz.openbmc_project.Sensor.Value.Unit.DegreesC" "_CODE_FILE" "../log_create_main.cpp" "_CODE_FUNC" "int generate_event(const std::string&, const nlohmann::json_abi_v3_11_2::json&)" "_CODE_LINE" "34" "_PID" "89391" emits-change writable
.EventId                                    property  s         ""                                                                                                                                                                                                                                                                                                                 emits-change writable
.Id                                         property  u         1                                                                                                                                                                                                                                                                                                                  emits-change writable
.Message                                    property  s         "xyz.openbmc_project.Sensor.Threshold.ReadingAboveUpperSoftShutdownThreshold"
Registry Generation

Redfish Message Registries are now being generated from phosphor-dbus-interfaces[1,2]. These are packaged into a separate phosphor-dbus-interface-redfish-registry package, which are not currently installed on the BMC, but would be installed at /usr/share/redfish-registry. I expect that bmcweb will eventually process these at build-time (like existing Redfish Message Registries) and these will never need to be installed, but the capability is there.

I’ve uploaded a sample Registry to Gist but you can also generate the full set from either a normal phosphor-dbus-interfaces meson build or check the packages-split tree in a bitbake build.

Nov 20, 2024

Modern event logs in OpenBMC

Current Status

I’ve been working on implementations of revamped event log design and wanted to give an update as to the current implementation progress.

Currently, the definition of the YAML format and event logging has been implemented through sdbusplus, phosphor-dbus-interfaces, and phosphor-logging; new errors can be defined in PDI and phosphor-logging can be called to record them. There is also a handy CLI tool written that allows users to mock events.

The following items are to be worked in the near future:

Allow-list / Block-list support in phosphor-logging.
Changing AdditionalData to be a dictionary.
Generation of the Redfish Message Registry.
Translation in bmcweb of phosphor-logging events to proper Redfish LogEntry format, including populating MessageArgs.
Adding ‘Hint’ support in Logging.Create.

Defining a new Event

Defining a new event requires writing an events.yaml file in PDI. Two decently featured examples are currently available: Sensor Thresholds (exclusively using standard Redfish events) and Leak Detector (defining OpenBMC-specific events).

Rather than doing custom sanity parsing of these YAML files, as was done for the sdbusplus interface definitions, I am leveraging JSON-Schema. This allows pretty decent explanation when the YAML file doesn’t meet expectations; I may add this capability to the interface YAML files at some point.

From the YAML, sdbusplus will generate a C++ class for an event. This class can either be thrown, which is useful for sdbusplus servers that want the event to be sent back as part of the dbus response, or “committed” to the phosphor-logging record. The commit APIs support both blocking and async variants.

See this test-case as an example:

        path = co_await lg2::commit(data->client_ctx,
                                    LoggingCleared("NUMBER_OF_LOGS", 6));

In the above code it might be noticed that the event metadata is taken as {string, data} pairs. There is compile-time checking to ensure the correct metadata has been provided.

### Missing metadata
../test/log_manager_dbus_tests.cpp:131:32: error: no matching function for call to ‘sdbusplus::event::xyz::openbmc_project::Logging::Cleared::Cleared()’
  131 |         { throw LoggingCleared(); }, LoggingCleared);

### Incorrect metadata name
../subprojects/sdbusplus/include/sdbusplus/utility/consteval_string.hpp: In member function ‘virtual void phosphor::logging::test::TestLogManagerDbus_GenerateSimpleEvent_Test::TestBody()’:
../test/log_manager_dbus_tests.cpp:130:5:   in ‘constexpr’ expansion of ‘sdbusplus::utility::consteval_string<sdbusplus::utility::details::consteval_string_holder<15>{"NUMBER_OF_LOGS"}>("LOGS")’
../subprojects/sdbusplus/include/sdbusplus/utility/consteval_string.hpp:41:25: error: call to non-‘constexpr’ function ‘static void sdbusplus::utility::consteval_string<V>::report_error(const char*) [with consteval_string_holder<...auto...> V = sdbusplus::utility::details::consteval_string_holder<15>{"NUMBER_OF_LOGS"}]’
   41 |             report_error("String mismatch; check parameter name.");

### Incorrect metadata type
../test/log_manager_dbus_tests.cpp:131:50: error: invalid conversion from ‘const char*’ to ‘uint64_t’ {aka ‘long unsigned int’} [-fpermissive]
  131 |         { throw LoggingCleared("NUMBER_OF_LOGS", "string"); }, LoggingCleared);
      |                                                  ^~~~~~~~
      |                                                  |
      |                                                  const char*

Using the CLI

I also wrote a log-create CLI which is useful for testing events, which is now installed by the phosphor-logging package. Running log-create --list will enumerate all of the event types that phosphor-logging is aware of:

$ log-create --list
Known events:
    xyz.openbmc_project.Logging.Cleared
    xyz.openbmc_project.Sensor.Threshold.InvalidSensorReading
    ...

Individual events can be created by specifying the event name and passing the metadata as JSON (if any metadata is required):

$ log-create \
    xyz.openbmc_project.Sensor.Threshold.ReadingAboveUpperSoftShutdownThreshold \
    --json '{ "SENSOR_NAME": "Inlet Temperature", "READING_VALUE": 98.6, "UNITS": "xyz.openbmc_project.Sensor.Value.Unit.DegreesC", "THRESHOLD_VALUE": 40 }'

This will result in an event such as (some interfaces and fields pruned):

$ busctl --user introspect xyz.openbmc_project.Logging /xyz/openbmc_project/logging/entry/1 -l
xyz.openbmc_project.Logging.Entry           interface -         -                                                                                                                                                                                                                                                                                                            -
.GetEntry                                   method    -         h                                                                                                                                                                                                                                                                                                            -
.AdditionalData                             property  as        8 "READING_VALUE=98.6" "SENSOR_NAME=\"Inlet Temperature\"" "THRESHOLD_VALUE=40.0" "UNITS=\"xyz.openbmc_project.Sensor.Value.Unit.DegreesC\"" "_CODE_FILE=../log_create_main.cpp" "_CODE_FUNC=int generate_event(const std::string&, const nlohmann::json_abi_v3_11_2::json&)" "_CODE_LINE=34" "_PID=1931265" emits-change writable
.EventId                                    property  s         ""                                                                                                                                                                                                                                                                                                           emits-change writable
.Id                                         property  u         1                                                                                                                                                                                                                                                                                                            emits-change writable
.Message                                    property  s         "xyz.openbmc_project.Sensor.Threshold.ReadingAboveUpperSoftShutdownThreshold"                                                                                                                                                                                                                                emits-change writable
.Resolution                                 property  s         ""                                                                                                                                                                                                                                                                                                           emits-change writable
.Resolved                                   property  b         false                                                                                                                                                                                                                                                                                                        emits-change writable
.ServiceProviderNotify                      property  s         "xyz.openbmc_project.Logging.Entry.Notify.NotSupported"                                                                                                                                                                                                                                                      emits-change writable
.Severity                                   property  s         "xyz.openbmc_project.Logging.Entry.Level.Critical"                                                                                                                                                                                                                                                           emits-change writable
.Timestamp                                  property  t         1732137165521                                                                                                                                                                                                                                                                                                emits-change writable
.UpdateTimestamp                            property  t         1732137165521                                                                                                                                                                                                                                                                                                emits-change writable

Apr 1, 2022
sdbusplus: object_t constructor signals
TL;DR

The sdbusplus::server::object_t constructor that takes a bool deferSignal is going away.
```
-    object(bus_t& bus, const char* path, bool deferSignal) :
-        object(bus, path,
-               deferSignal ? action::defer_emit : action::emit_object_added)
-    {
-        // Delegate to default ctor
-    }
```
The bool deferSignal argument should be replaced with one of the action enums:
```
    enum class action
    {
        /** sd_bus_emit_object_{added, removed} */
        emit_object_added,
        /** sd_bus_emit_interfaces_{added, removed} */
        emit_interface_added,
        /** no automatic added signal, but sd_bus_emit_object_removed on
         *  destruct */
        defer_emit,
        /** no interface signals */
        emit_no_signals,
    };
```
If you were previously using deferSignal = true you likely want either defer_emit or emit_no_signals but you need to read on to know which one.

Background

Missing InterfaceRemoved signals?

Lei YU recently posted to the mailing list about an issue he was observing with phosphor-logging where log entries did not always send the InterfacesRemoved signals. After some discussion between a few of us in the review of a simple fix Lei YU proposed we realized there is a fundamental issue in the sdbusplus::server::object_t API with respect to these signals.

sd_bus APIs

At a DBus level there are two signals used to indicate that an object has shown up on or been removed from the bus, InterfacesAdded and InterfacesRemoved, both of which are from the org.freedesktop.DBus.ObjectManager interface. The systemd sd-bus API provides the following functions:
- sd_bus_emit_interfaces_added
- sd_bus_emit_interfaces_removed
- sd_bus_emit_object_added
- sd_bus_emit_object_removed
The interface-level functions take a list of interfaces and create the corresponding Interfaces{Added,Removed} signal. The object-level functions are simply helper functions which create the signals for all interfaces the sd-bus ObjectManager is aware of having resided at that object-path.

sdbusplus::server::object_t

sdbusplus has two relevant classes here: server::object_t and server::interface_t. Typically the interface_t is only used by the sdbus++ generated server bindings and it provides constructor/destructor hooks to register the interface with the ObjectManager, but it also has emit_added and emit_removed functions which can be used to explicitly emit the Interfaces{Added,Removed} signals. These functions are rarely used. The object_t class is much more widely used and what it does is stitch together multiple generated server classes into a single C++ object. Often you will observe an override class such as:
```
class LocalObject : public object_t<InterfaceA, InterfaceB>
{
   // ...

   void methodFromInterfaceA(...) override // method call
   {
       // ...
   }

   size_t propertyFromInterfaceB() override // property get
   {
      // ...
   }
}
```
Originally, the object_t class would automatically send the Interface{Added,Removed} signals, and it still does so by default, but a parameter was added to control the signal behavior. First the parameter was a boolean (deferSignals) and later it was changed to an enumeration (action) but the boolean form was preserved for backwards compatibility with old code. It is around this attempted automatic signal behavior that the issue Lei YU observed stems.

Object Lifecycles

Poorly Performing Simple Object

The simplest object life-cycle is that you create an object and it already has its properties set to a valid initial value, so you want to immediately advertise it on the dbus and you want it to report its removal when you destruct it. This is what object_t does by default, with the action::emit_object_added, but it is almost never what you actually want. Why?
- Rarely are the default property values correct for your object. So by using this you’ve advertised the object before it is fully initialized. You are either sending a bunch of spurious PropertiesChanged signals immediately or you lied in the property values of the InterfacesAdded signal, or both. This reduces the utility of the InterfacesAdded signal and/or causes performance issues by a flood of PropertiesChanged signals.
- On daemon start-up, you shouldn’t have claimed a bus-name until all your initial state objects are created, so these signals are uselessly sent from an anonymous DBus connection (:1:123 style).
If you are using the default constructor (or explicitly adding action::emit_object_added) your application probably isn’t being a good DBus citizen but it is likely working as-is and other than the lies told in the InterfacesAdded no one is likely to notice. At a future date I will probably remove the default=action::emit_object_added.

Proper Simple Dynamic Object

For most use-cases the proper behavior for a simple dynamically created object is to use the action::defer_emit on object construction, set up all the properties using the skipSignal=true property-set overrides, and then call this->emit_object_added(). This prohibits the initial automatic InterfaceAdded signal, disables all the spurious PropertiesChanged signals, sends a nice (and correct) InterfacesAdded signal with the correct initial property state of your object, and lastly automatically sends InterfacesRemoved when you decide to delete the object. Perfect!

Except, you’ll notice I used the word “dynamic” here. This means your daemon has been up and running and you have already claimed a bus-name. What about the objects your daemon is creating on start up (or maybe restoring from persistent storage as in the case of phosphor-logging)? It is a little more complicated and is the use-case of the issue. But, first, let’s talk about a few other use cases.

Permanent Sub-Objects

In the phosphor-hwmon repository I noticed an implementation pattern where a object_t<Sensor::Value> is created to hold the primary information about the Sensor. In some cases, depending on additional data, something like a std::unique_ptr<object_t<Sensor::Threshold::Critical>> is created at the same object path. This critical threshold object I am calling a “permanent sub-object” because the lifetime of it matches that of the primary object (the Sensor::Value in this case).

The best way to handle this pattern is pretty similar to the Simple Dynamic Object. In between setting the primary object’s properties and calling emit_object_added() we create any sub-objects and set their properties. Then, the primary object’s emit_object_added() will include all the interfaces for all the sub-objects. Great!

There is still the question of how do we set the action parameter for the sub-objects. The answer now is action::emit_no_signals. We never want the sub-object to deal with its own lifetime signals! If we did they’d also be the lifetime signals for the parent object because they are all residing at the same dbus object-path (Uh-oh!).

Temporary Sub-Objects

Another pattern I’ve seen is a primary object which contains mostly static data, but sometimes creates a temporary object_t<Progress> sub-object. This is temporary in the sense that the lifetime of the Progress is shorter than the primary object; once the operation is done, the Progress is eventually deleted.

In this pattern, on lifetime beginning and end of the Progress interface we only want the Progress interface included in the Interfaces{Added,Removed} signals. The way to handle this is to use action::emit_interfaces_added. This will ensure that sd_bus_emit_interfaces_* functions are used instead of sd_bus_emit_object_* functions. When the Progress object is destructed it will similar only send a InterfacesRemoved containing itself.

Start-up Objects

At the beginning I mentioned one of the flaws of using action::emit_object_added was:

On daemon start-up, you shouldn’t have claimed a bus-name until all your initial state objects are created, so these signals are uselessly sent from an anonymous DBus connection (:1:123 style).

So, there is still an issue of what to do on application start-up where you have a set of initial objects.

(You don’t want to grab the bus-name early because then mapper is aware of your application and you then need to send all the InterfacesAdded signals, which slows everything down.)

The ideal sequence is something like:
1. Create objects without sending any signals.
2. Claim bus-name.
3. Process forever…
  1. Send InterfacesRemoved on original objects if they are ever destructed.
We can get away with (1) because mapper listens for org.freedesktop.DBus.NameOwnerChanged signals and then queries the daemon for everything it has on the dbus.

The problem is getting an implementation for (3.1) and the source of the original issue. In phosphor-logging, the defer_emit was set but emit_object_added was never called, so the destructor didn’t use to do anything. There was actually no way to specify the behavior from (1) + (3.1)!

Solution

We use to have applications using action::defer_emit to attempt to do both the “Permanent Sub-Object” and “Start-up Object” patterns and we had no way to differentiate them. Many applications are still using the boolean deferSignal = true constructor parameter, which is the same as defer_emit. We need some way to be able to deduce which pattern desired so we are going to change the API to be explicit.
- The action emit_no_signals is being added, which should be used for the “Permanent Sub-Object” pattern to indicate “this C++ object should never deal with its own signals; they are covered elsewhere.”
- The action defer_emit is being changed in the destruct path to always send InterfacesRemoved signals. This covers the “Start-up” problem and all uses of defer_emit in the codebase already desired this behavior. defer_emit now means “I don’t want the InterfacesAdded signal now and maybe I’ll send them later, but I definitely want InterfacesRemoved”.
- The boolean deferSignal constructor overload is being deleted.
  - All applications will need to be fixed up to be explicit in action.
  - This gives us an avenue to review all uses of the deferSignal = true pattern and fix them before we change defer_emit’s behavior.
I have implemented the sdbusplus changes for this:
- Add emit_no_signals [merged]
- Change defer_emit destructor behavior
- Remove boolean constructor
I have reviewed all cases of defer_emit in the openbmc organization and they are all compatible with the destructor change.

I am working through all repositories pulled into the CI-tested machines and ensuring they compile with the “Remove boolean constructor” change. If you are a maintainer and see a commit titled “sdbusplus: object: don’t use ‘bool’ argument constructor” this is the proposed fix. The important thing to do here is to review the additions of defer_emit or emit_no_signals and ensure the code aligns with one of the earlier patterns (and I’ve chosen the right one).
Mar 23, 2022
Using Meson subproject [provide]s
Specifying dependencies

I previously introduced how to find dependencies using meson subproject wrapfiles, but I suggested using the verbose fallback argument to dependency. I also wrote:

I think there is a method to add the fallback directives into the wrap file itself but I haven’t played with that yet.

I’ve since learned how to do this and have been updating most of the repos. It greatly reduces the noise in meson.build dependency expression.

Depending on a simple library

If the repository you’re depending on is just providing a library, then the fallback can be entirely removed. Instead the wrapfile is the proper way to specify the fallback information in a [provide] section.

As an example, phosphor-networkd had a change to the meson.build to remove fallback:
```
- phosphor_logging_dep = dependency(
-   'phosphor-logging',
-   fallback: ['phosphor-logging', 'phosphor_logging_dep'])
+ phosphor_logging_dep = dependency('phosphor-logging')
```
and a change to phosphor-logging.wrap to add the same information:
```
+ [provide]
+ phosphor-logging = phosphor_logging_dep
```
In the provide statement, the left hand side is the dependency name and the right hand side is the meson variable in the subproject holding the dependency.

Exposing an executable

Sometimes a repository exposes an executable which is needed as part of a build process such as for generating code. The same phosphor-networkd change had a fairly complex meson directive for finding some of these executables:
```
sdbusplus_dep = dependency('sdbusplus', required: false)
if sdbusplus_dep.found() and sdbusplus_dep.type_name() != 'internal'
  sdbusplusplus_prog = find_program('sdbus++', native: true)
  sdbuspp_gen_meson_prog = find_program('sdbus++-gen-meson', native: true)
else
  sdbusplus_proj = subproject('sdbusplus', required: true)
  sdbusplus_dep = sdbusplus_proj.get_variable('sdbusplus_dep')
  sdbusplusplus_prog = sdbusplus_proj.get_variable('sdbusplusplus_prog')
  sdbuspp_gen_meson_prog = sdbusplus_proj.get_variable('sdbuspp_gen_meson_prog')
endif
```
Instead these can be expressed in the [provide] section using the special program_names directive and the simple native meson find_program function can be used.
```
[provide]
sdbusplus = sdbusplus_dep
program_names = sdbus++, sdbus++-gen-meson
```
```
sdbusplus_dep = dependency('sdbusplus')
sdbusplusplus_prog = find_program('sdbus++', native: true)
sdbuspp_gen_meson_prog = find_program('sdbus++-gen-meson', native: true)
```
May 1, 2021
sdbus++: Irritating camelCase from acronyms
The sdbus++ generator we use to generate server bindings from phosphor-dbus-interfaces has long had an irritating behavior around how it tries to convert property and method names from YAML to generated C++ function names. It had been using a trivial call to inflection.camelize to create a lowerCamelCase version of what it found in the YAML. The problem with this is that many properties, especially in the networking space, are acronyms. The camelize function would turn a property like MACAddress into an awkward mACAddress.

Five years later, I’m getting around to fixing this behavior. Going forward the generator will handle acronyms in, what I think is, a reasonable way. Some examples:
- MACAddress becomes macAddress.
- BMC becomes bmc.
- IPv6Address becomes ipv6Address.
Generally speaking what the code does is:
1. First turn the name into UpperCamelCase using Inflection.
2. Identify if the multiple letters at the beginning are upper case: an acronym!
3. Turn everything except the last upper case letter at the beginning to lower case.
  - But, there is a special case to handle ‘IPv6’. Any set of upper case letters that has a “v” for “version” followed by a number (ie. [A-Z]+v[0-9]+) is treated as a full acronym.
There are probably a few cases that this doesn’t cover in the most ideal way, but I didn’t find any in the current phosphor-dbus-interfaces. One that comes to mind is a sequence of multiple acronyms like DHCPDNSServers would become dhcpdnsServers, but without a list of known acronyms it would be hard to figure out DHCP and DNS are two different acronyms.

There is already quite a bit of code that uses the awkward acronyms when instantiating instances of generated classes, so I had to define a way to independently migrate the sdbus++ code from the instantiating repositories. What I’ve done is define a preprocessor constant SDBUSPP_NEW_CAMELCASE which can be used as a key to use the “new format”.

My plan to get this integrate is as follows:
1. Push up to Gerrit the change to sdbus++ for review. (done)
2. Find all occurrences I can of old-style acronyms in the openbmc codebase and push up fixes utilizing the SDBUSPP_NEW_CAMELCASE key. These will be under the Gerrit topic sdbuspp_camelcase. (done)
3. After #2’s are all merged, make a test commit to openbmc/openbmc of the sdbus++ changes to ensure I haven’t missed something in step 2, and make fixes as necessary. (done 2021-05-12)
4. Remove the #define SDBUSPP_NEW_CAMELCASE from sdbus++ after #3 is merged.
5. Clean up the #else side of the #ifdef’s in #2 so that the old-style acronyms are no longer present.
This work should happen essentially as fast as reviews from #2 can be done, so any help to make that speed along would be greatly appreciated!
Apr 30, 2021
phosphor-logging now using Meson.

As of this commit, phosphor-logging is now enabled to be built with meson instead of autotools and it can be imported as a meson-subproject. This means that now all the fundamental libraries used in OpenBMC are available as meson subprojects, so you should be able to structure any meson-based openbmc repository such that it can compile easily on any typical Linux development system outside of an OE-SDK.

I plan to work today on getting the corresponding Yocto recipes updated as well.
Apr 18, 2021
Using Meson subprojects with OpenBMC
Motivation

For OpenBMC code repositories, we have a number of different ways you can use to compile the code:
1. Using bitbake to build the recipe and/or a complete flash image.
2. Using devtool inside an oe-init-build-env.
3. Using the bitbake SDK from bitbake <image> -c populate_sdk.
4. Using the openbmc run-unit-test-docker script, which uses Docker to build all the required dependencies and launch the same unit-test framework used by Jenkins (maybe with my launch aid).
In the last few days I’ve been working to ensure that projects I maintain can also be compiled entirely isolated, using basic Linux distro packages and Meson subprojects to fill in everything else. You might wonder why we would support yet another build workflow. The primary reason is that for speed in both my “start the day” and “develop / compile / test” operations.
...Continued
Aug 7, 2015
How I set up my email
Since we released the OpenPower Firmware a year ago, I’ve been spending a lot more time on github and mailing lists. I was finding that my combination of gmail and Lotus Notes was getting cumbersome. I’ve had a few cases where a mailing list I was responding to stripped out my messages because Notes created my email as an HTML attachement. So, I’ve decided to setup an entirely command-line email environment for any open source work I do. I arrived at using:
- mutt
- msmtp
- offlineimap
...Continued

Posts

Current Status

AdditionalData

Registry Generation

Current Status

Defining a new Event

Using the CLI

TL;DR

Background

Missing InterfaceRemoved signals?

sd_bus APIs

sdbusplus::server::object_t

Object Lifecycles

Poorly Performing Simple Object

Proper Simple Dynamic Object

Permanent Sub-Objects

Temporary Sub-Objects

Start-up Objects

Solution

Specifying dependencies

Depending on a simple library

Exposing an executable

Motivation