Observer not working for `smapi`

[ydirson]

In v24.39.1, we noticed that the observer.py wrapper does not get called when an observer is enabled on the smapi component.

The traces added in #6280 reveal the following exception:

Jan 28 10:48:01 xcpng83-bzkcpvhy xapi: [error||0 |check if component smapi is enabled  D:181f882cc62e|xapi_observer_components] is_component_enabled(smapi) inner got exception: Db_exn.DBCache_NotFound("missing table", "Observer", "")

Readablized stack trace:

Raised at Xapi_database__Db_cache_types.TableSet.find in file "ocaml/database/db_cache_types.ml", line 262, characters 22-73
Called from Xapi_database__Db_cache_impl.read_refs in file "ocaml/database/db_cache_impl.ml", line 255, characters 12-70
Called from Db_actions.DB_Action.Observer.get_all in file "ocaml/xapi/db_actions.ml", line 21421, characters 40-69
Called from Xapi_observer_components.is_component_enabled.(fun) in file "ocaml/xapi/xapi_observer_components.ml", line 83, characters 26-56

From what I understand:

• the code calls Db.Observer.get_all
• that one is generated code making use of an in-memory cache
• said cache misses the Observer table even when the XAPI state.db has it

What could be causing this?

[contificate]

This is very peculiar. Usually, this exception is seen at startup (e.g. if you moved an old build to a host).

---

It would be worth instrumenting in some way to see what database the Context.t used by Xapi_observer_components believes it has: the exec_with_new_task handling should just yield a context that takes reference to the master database.

Do other DB actions - regarding Observer - also fail? Something like Observer.get_by_name_label (fully auto-generated, Server's local action will immediately call into Db_actions).

[ydirson]

Do other DB actions - regarding Observer - also fail? Something like Observer.get_by_name_label

From python it looks pretty OK:

s = get_xapi_session()
xapi = s.xenapi
res = xapi.Observer.get_by_name_label("ydi-obs2")
print(f"got: {res}")
print(f"{xapi.Observer.get_name_label(res[0])}")

got: ['OpaqueRef:b1423e14-2859-7f0d-4a5a-dc901b401e07']
ydi-obs2

[ydirson]

Do other DB actions - regarding Observer - also fail? Something like Observer.get_by_name_label

From python it looks pretty OK:

Just ignore that - I should have checked that first... from python the get_all() call works well too, digging...

[contificate]

Is there a possibility that this is doing a DB action prior to the database being initialised on startup?

A lot of code in Xapi is written in a way where evaluation of required ambient state is delayed until first use: e.g. any code using Xapi_globs can't reliably be done at module initialisation, as the values likely won't have been initialised yet. These cases technically amount to trying to mitigate race conditions, but usually it's expected that enough of Xapi must be "up" for various code paths to be reached anyway.

[ydirson]

Is there a possibility that this is doing a DB action prior to the database being initialised on startup?

I don't think so, as this happens systematically, every time I do a common operation (mainly testing with VM.start and VM.shutdown), and the observer does send telemetry data for xapi and xenopsd components.

[ydirson]

Checked adding a call to get_by_name_label() in is_component_enabled, it does fail with a similar exception.

[contificate]

Checked adding a call to get_by_name_label() in is_component_enabled, it does fail with a similar exception.

It may be worth trying some other DB actions, affecting other tables, in the same place.

---

As an aside, it would be worth adding stats : Db_ref.t -> (string * int) list to the DB_ACCESS signature and creating relevant implementations for the remote DB protocol implementations. Then, you'd be able to call it like:

let open Xapi_database in
let r = Context.database_of __context in
let module DB = (val Db_cache.get r : Db_interface.DB_ACCESS) in
let stats = DB.stats r in
List.iter (fun (table, count) -> D.debug "%s => %d" table count) stats; ...

This really should've been part of the DB_ACCESS signature, as it's simpler when you just want rough statistics.

[gthvn1]

It looks like the problem is that the check if component is enabled is done when registering SMAPIv1 plugins. But, when xapi starts, the registration of plugins (call to SM.register) is done before the initialization of the database.

So when we check if SMAPI component is enabled it fails because the database is not yet active (and it is what you see with missing table Observer). And I think that once it has failed it won't try again and it is considered that SMAPI component is not enabled and so we don't have any traces. I quickly tried to move the initialisation of DB before the registration of SMAPI plugins but it looks like we cannot start the database too early as well.

[psafont]

@snwoods wasn't this something you fixed some months ago?

[gthvn1]

For info, I tried on xcp-ng 8.3 (so with xapi 25.6.0). I don't see new fixes but I maybe missed them. Basically for testing I move the initialization of SM plugins after the creation of the database and it looks that now there are some configuration that are created for SMAPI observer:

# cat /etc/xensource/observer/smapi/enabled/0cb99fc5-6527-7655-8235-ea63cc3a665d.observer.conf
OTEL_SERVICE_NAME='smapi'
OTEL_RESOURCE_ATTRIBUTES='xs.pool.uuid=0496aa55-4e6f-363d-6578-4ab872ddfb9e,xs.host.name=xcp-gtn-ip13,xs.host.uuid=cb043a21-9c51-4418-a1e8-e7079ac6dc1a,xs.observer.name=local%20observer,service.name=smapi'
XS_EXPORTER_ZIPKIN_ENDPOINTS=''
XS_EXPORTER_BUGTOOL_ENDPOINT='/var/log/dt/zipkinv2/json'

Basically I did that (but maybe there are some impact so it was just for testing that if the xapi db is created it seems to work:

diff --git a/ocaml/xapi/xapi.ml b/ocaml/xapi/xapi.ml
index 2834cd15b..b4a8d6167 100644
--- a/ocaml/xapi/xapi.ml
+++ b/ocaml/xapi/xapi.ml
@@ -1064,21 +1064,6 @@ let server_init () =
                 if !Xapi_globs.tgroups_enabled then
                   Tgroup.Cgroup.init Xapi_globs.xapi_requests_cgroup
             )
-          ; ( "Registering SMAPIv1 plugins"
-            , [Startup.OnlyMaster]
-            , Sm.register ~__context
-            )
-          ; ( "Initialising SMAPIv1 state"
-            , []
-            , Storage_smapiv1_wrapper.initialise
-            )
-          ; ( "Starting SMAPIv1 proxies"
-            , [Startup.OnlyMaster]
-            , Storage_access.start_smapiv1_servers
-            )
-          ; ("Starting SM service", [], Storage_access.start)
-          ; ("Starting SM xapi event service", [], Storage_access.events_from_sm)
-          ; ("Killing stray sparse_dd processes", [], Sparse_dd_wrapper.killall)
           ; ( "Registering http handlers"
             , []
             , fun () -> List.iter Xapi_http.add_handler (common_http_handlers ())
@@ -1114,6 +1099,21 @@ let server_init () =
             , [Startup.OnlyMaster]
             , Xapi_db_upgrade.hi_level_db_upgrade_rules ~__context
             )
+          ; ( "Registering SMAPIv1 plugins"
+            , [Startup.OnlyMaster]
+            , Sm.register ~__context
+            )
+          ; ( "Initialising SMAPIv1 state"
+            , []
+            , Storage_smapiv1_wrapper.initialise
+            )
+          ; ( "Starting SMAPIv1 proxies"
+            , [Startup.OnlyMaster]
+            , Storage_access.start_smapiv1_servers
+            )
+          ; ("Starting SM service", [], Storage_access.start)
+          ; ("Starting SM xapi event service", [], Storage_access.events_from_sm)
+          ; ("Killing stray sparse_dd processes", [], Sparse_dd_wrapper.killall)
           ; ( "bringing up management interface"
             , []
             , bring_up_management_if ~__context

[snwoods]

@snwoods wasn't this something you fixed some months ago?

Hmm I did make a fix in this area, but I'm not sure if it's the same. Is this an issue for smapiv1 or smapiv3? This is the fix I made: #6488 Similarly, it was an issue with a race condition on startup, xapi-storage-script/main.ml only checked whether to enable tracing for smapiv3 on startup. So if the observer was created/enabled after startup (or the race condition meant the observer wasn't created yet at startup) smapiv3 tracing would be disabled.
I've replaced this startup check with a full observer forwarder which send messages to xapi-storage-script when the observer is created/destroyed/enabled.

If this issue is for smapiv1, my fix won't help. Quick sanity check: the observer for smapi is still deemed "experimental", so it is off by default. Do you have observer-experimental-components="" in /etc/xapi.conf?

[gthvn1]

This issue is for smapiv1.
No I don't have observer-experimental-components="" in /etc/xapi.conf. I will add it and run more tests.
Thanks for pointing that because I didn't know about it.

[gthvn1]

So by setting observer-experimental-components="" and by moving the initialization of SMAPI plugins after the initialization of the database I'm able to activate smapi traces. I will have a closer look to your patch #6488 because maybe moving the initialization of SMAPI plugin has some side effects that I don't see.
But at least with my patch I have and the correct setup in /etx/xapi.conf I see:

[gthvn1]

So now that I know how it works it looks like the issue we see at the beginning Jan 28 10:48:01 xcpng83-bzkcpvhy xapi: [error||0 |check if component smapi is enabled D:181f882cc62e|xapi_observer_components] is_component_enabled(smapi) inner got exception: Db_exn.DBCache_NotFound("missing table", "Observer", "") is not fatal.
This issue is, as explained, because database is not active when checking the SMAPI component. And I was able to fix it be moving the initialization of SM after the initialization of database. But I have a setup with the "vanilla" xcp-ng 8.3, (so I still have the issue) but with the correct setup in /etc/xapi.conf (that is observer-experimental-components="") and I have the SMAPI traces. So the error is still there but not fatal.
I don't see in the documentation the information about observer-experimental-components="". I can at least update the doc :). And if you think that moving initialization of the SM plugins after the initialization of the XAPI DB is correct I can also submit a PR with the patch.