Fix logging always using the device object within shared methods -- SIMICS-11346

Author: lwaern-intel

RELEASENOTES-1.4.docu

@@ -513,4 +513,9 @@
       within a port, bank or subdevice that is itself declared within an object
       array would lead to the type of that attribute being incorrectly
       registered <bug number="SIMICS-21474"/>.</add-note></build-id>
+  <build-id value="next"><add-note> Fixed a bug where log statements within
+      <tt>shared</tt> methods would always use the device's configuration object
+      as the log object instead of the configuration object of the nearest
+      enclosing <tt>device</tt>, <tt>port</tt>, <tt>bank</tt> or
+      <tt>subdevice</tt> <bug number="SIMICS-11346"/>.
 </rn>

include/simics/dmllib.h

@@ -3130,10 +3130,24 @@ _DML_get_single_hook_attr(void *_hook, uintptr_t _aux) {
 }
 
 
-UNUSED static uint64 _identity_to_key(_identity_t id) {
+UNUSED static inline uint64 _identity_to_key(_identity_t id) {
         return (uint64)id.id << 32 | (uint64)id.encoded_index;
 }
 
+typedef struct {
+    uint32 port_obj_offset;
+    uint32 index_divisor;
+} _dml_log_object_assoc_t;
+
+UNUSED static inline conf_object_t *
+_identity_to_logobj(const _dml_log_object_assoc_t *object_assocs,
+                    conf_object_t *dev, _identity_t id) {
+    _dml_log_object_assoc_t obj_assoc = object_assocs[id.id - 1];
+    if (!obj_assoc.index_divisor) return dev;
+    return ((conf_object_t **)((char *)dev + obj_assoc.port_obj_offset))[
+        id.encoded_index / obj_assoc.index_divisor];
+}
+
 static attr_value_t
 _serialize_array_aux(const uint8 *data, size_t elem_size,
                      const uint32 *dimsizes, uint32 dims,

py/dml/c_backend.py

@@ -2143,7 +2143,38 @@ def generate_object_vtables_array():
         items.append(pointer)
     init = '{%s}' % (', '.join(items),)
     add_variable_declaration(
-        'void * const _object_vtables[%d]' % (len(dml.globals.objects)),
+        f'void * const _object_vtables[{len(dml.globals.objects)}]', init)
+
+def generate_log_object_assocs_array():
+    items = []
+    for node in dml.globals.objects:
+        object_node = (node if node.objtype in {'device', 'bank',
+                                                'subdevice', 'port'}
+                       else node.object_parent)
+        if (object_node is not dml.globals.device
+            # Anonymous banks
+            and not (compat.dml12_misc in dml.globals.enabled_compat
+                     and object_node.ident is None)
+            # HACK compile errors may lead to .name of nodes never being set.
+            # This issue has proven difficult to fix due to multiple technical
+            # debts, most egregiously that the various uses of
+            # dml.globals.objects and dml.globals.hooks don't properly take
+            # into account the possibility of objects becoming rejected
+            and object_node.name is not None):
+            port_obj_offset = (
+                f'offsetof({crep.structtype(dml.globals.device)}, '
+                + f'{crep.cref_portobj(object_node, ())})')
+            index_divisor = str(reduce(
+                operator.mul,
+                itertools.islice(node.dimsizes, object_node.dimensions, None),
+                1))
+        else:
+            port_obj_offset = index_divisor = '0'
+        items.append(f'{{{port_obj_offset}, {index_divisor}}}')
+    init = f'{{{", ".join(items)}}}'
+    add_variable_declaration(
+        'const _dml_log_object_assoc_t '
+        + f'_log_object_assocs[{len(dml.globals.objects)}]',
         init)
 
 def generate_trait_method(m):
@@ -3297,6 +3328,7 @@ def generate_cfile_body(device, footers, full_module, filename_prefix):
     generate_events(device)
     generate_identity_data_decls()
     generate_object_vtables_array()
+    generate_log_object_assocs_array()
     generate_class_var_decl()
     generate_startup_calls_entry_function(device)
     generate_init_data_objs(device)

py/dml/codegen.py

@@ -167,8 +167,8 @@ def __init__(self, site, node, indices):
         self.indices = indices
 
     def fail(self, site):
-        return log_statement(site, self.node, self.indices, "error",
-                             mkIntegerLiteral(site, 1), None,
+        return log_statement(site, log_object(site, self.node, self.indices),
+                             "error", mkIntegerLiteral(site, 1), None,
                              "Uncaught DML exception")
 
 class ReturnFailure(Failure):
@@ -2640,6 +2640,15 @@ def stmt_log(stmt, location, scope):
     else:
         warn_mixup = probable_loggroups_specification(level)
 
+    # Acquire a subsequent log key and the logging object based on obj or trait
+    # identity
+    if location.method():
+        identity = ObjIdentity(site, location.node.parent, location.indices)
+        logobj = log_object(site, location.node, location.indices)
+    else:
+        identity = TraitObjIdentity(site, lookup_var(site, scope, "this"))
+        logobj = LogObjectFromObjIdentity(site, identity)
+
     if later_level is not None:
         adjusted_later_level = later_level = ctree.as_int(codegen_expression(
             later_level, location, scope))
@@ -2654,14 +2663,10 @@ def stmt_log(stmt, location, scope):
         global log_index
         table_ptr = TPtr(TNamed("ht_int_table_t"))
         table = mkLit(site, '&(_dev->_subsequent_log_ht)', table_ptr)
-        # Acquire a key based on obj or trait identity
-        if location.method():
-            identity = ObjIdentity(site, location.node.parent, location.indices)
-        else:
-            identity = TraitObjIdentity(site, lookup_var(site, scope, "this"))
         key = mkApply(site,
                       mkLit(site, "_identity_to_key",
-                            TFunction([TNamed('_identity_t')], TInt(64, False))),
+                            TFunction([TNamed('_identity_t')],
+                                      TInt(64, False))),
                       [identity])
 
         once_lookup = mkLit(
@@ -2690,8 +2695,8 @@ def stmt_log(stmt, location, scope):
         report(WLOGMIXUP(site, logkind, level, later_level, groups))
     fmt, args = fix_printf(fmt, args, argsites, site)
     return [mkCompound(site, pre_statements + [
-        log_statement(site, location.node, location.indices,
-                      logkind, adjusted_level, groups, fmt, *args)])]
+        log_statement(site, logobj, logkind, adjusted_level, groups, fmt,
+                      *args)])]
 @statement_dispatcher
 def stmt_try(stmt, location, scope):
     [tryblock, excblock] = stmt.args

py/dml/ctree.py

@@ -140,6 +140,7 @@
     'ObjIdentity',
     'TraitObjIdentity',
     'ObjTraitRef',
+    'LogObjectFromObjIdentity',
     'NodeArrayRef',
     'SessionVariableRef',
     'mkNodeRef', 'NodeRef',
@@ -165,6 +166,7 @@
     'as_int',
     'sym_declaration',
     'lookup_var',
+    'log_object',
     'log_statement',
 
     'all_index_exprs',
@@ -3534,6 +3536,19 @@ def ctype(self):
     def read(self):
         return "(%s).id" % (self.traitref.read(),)
 
+class LogObjectFromObjIdentity(Expression):
+    priority = dml.expr.Apply.priority
+    @auto_init
+    def __init__(self, site, identity):
+        crep.require_dev(site)
+
+    def ctype(self):
+        return TNamed('conf_object_t *')
+
+    def read(self):
+        return ('_identity_to_logobj(_log_object_assocs, &_dev->obj, '
+                + f'{self.identity.read()})')
+
 class TraitUpcast(Expression):
     @auto_init
     def __init__(self, site, sub, parent): pass
@@ -5033,7 +5048,11 @@ def lookup_var(site, scope, name):
     else:
         return sym.expr(site)
 
-def log_statement(site, node, indices, logtype, level, groups, fmt, *args):
+def log_object(site, node, indices):
+    return mkLit(site, crep.conf_object(site, node, indices),
+                 TPtr(TNamed("conf_object_t")))
+
+def log_statement(site, logobj, logtype, level, groups, fmt, *args):
     if logtype in ['error', 'critical']:
         lvl = []
     else:
@@ -5049,8 +5068,6 @@ def log_statement(site, node, indices, logtype, level, groups, fmt, *args):
                      TPtr(TInt(8, True, const=True))])
     fun = mkLit(site, logfunc, TFunction(inargtypes, TVoid(), varargs=True))
 
-    logobj = mkLit(site, crep.conf_object(site, node, indices),
-                   TPtr(TNamed("conf_object_t")))
     x = Apply(site, fun,
               lvl +
               [ logobj,

py/dml/int_register.py

@@ -57,10 +57,9 @@ def codegen_get_name(impl, indices, inargs, outargs, site):
         [mkCopyData(site, regname, name),
          mkIf(site,
               mkNot(site, as_bool(name)),
-              log_statement(site, bank, indices, "error",
-                                       None, None,
-                                       "There is no register with number %d",
-                                       num)),
+              log_statement(site, log_object(site, bank, indices), "error",
+                            None, None, "There is no register with number %d",
+                            num)),
          return_success(site)])
 
 def codegen_get_number(impl, indices, inargs, outargs, site):
@@ -105,8 +104,8 @@ def codegen_get_number(impl, indices, inargs, outargs, site):
                          [mkCopyData(site,
                                      mkIntegerConstant(site, -1, True),
                                      num),
-                          log_statement(site, bank, indices, "error",
-                                        None, None,
+                          log_statement(site, log_object(site, bank, indices),
+                                        "error", None, None,
                                         "There is no register with name %s",
                                         name)])),
          return_success(site)])
@@ -155,9 +154,8 @@ def codegen_read(impl, indices, inargs, outargs, site):
                                   regvar,
                                   reg_table]),
                          val),
-              log_statement(site, bank, indices, "error",
-                            None, None,
-                            "There is no register with number %d",
+              log_statement(site, log_object(site, bank, indices), "error",
+                            None, None, "There is no register with number %d",
                             num)),
          return_success(site)])
 
@@ -203,8 +201,7 @@ def codegen_write(impl, indices, inargs, outargs, site):
                                              regvar,
                                              reg_table,
                                              val])),
-              log_statement(site, bank, indices, "error",
-                            None, None,
-                            "There is no register with number %d",
+              log_statement(site, log_object(site, bank, indices), "error",
+                            None, None, "There is no register with number %d",
                             num)),
          return_success(site)])

test/1.2/registers/T_instrumentation.py

@@ -38,11 +38,11 @@
 instrumentation_connection_order.test(obj, subscribe_b1, order_b1)
 
 instrumentation_access_inquire.test(obj, subscribe_b2)
-instrumentation_access_set_missed.test(obj, subscribe_b1, obj.bank.b1)
+instrumentation_access_set_missed.test(obj, subscribe_b1)
 instrumentation_access_set_offset.test(obj, subscribe_b1)
 instrumentation_access_set_value.test(obj, subscribe_b1)
 instrumentation_access_suppress.test(obj, subscribe_b1)
-instrumentation_access_value_at_miss.test(obj, subscribe_b1, obj.bank.b1)
+instrumentation_access_value_at_miss.test(obj, subscribe_b1)
 instrumentation_bank_array.test(obj, subscribe_ba[0], subscribe_ba[1])
 instrumentation_callback_args.test(obj, subscribe_b1)
 instrumentation_callback_inquiry.test(obj, subscribe_b1)
@@ -53,7 +53,7 @@
 instrumentation_endianness_overlapping.test(obj.bank.be, 0x010203040A0B0C0D)
 instrumentation_endianness_overlapping.test(obj.bank.le, 0x0A0B0C0D01020304)
 instrumentation_instrument_all.test(obj, subscribe_b1)
-instrumentation_instrument_edge.test(obj, subscribe_b1, obj.bank.b1)
+instrumentation_instrument_edge.test(obj, subscribe_b1)
 instrumentation_overlapping_order.test(obj, subscribe_b1)
 instrumentation_range.test(obj, subscribe_b1)
 instrumentation_subscribe_multiple.test(obj, subscribe_b1, subscribe_b2)

test/1.4/lib/T_map_target_connect.py

@@ -53,13 +53,13 @@
 
 obj.x_address = 0
 obj.log_level = 2
-with stest.expect_log_mgr(obj, log_type="spec-viol"):
+with stest.expect_log_mgr(obj.bank.z, log_type="spec-viol"):
     rex = re.compile("^failed to read 8 bytes @ 0x0")
     with stest.expect_log_mgr(obj, log_type="info", regex=rex):
         _ = obj.x_value
 
     rex = re.compile("^failed to write 8 bytes @ 0x0")
-    with stest.expect_exception_mgr(simics.SimExc_Attribute):
-        with stest.expect_log_mgr(obj, log_type="info", regex=rex):
+    with stest.expect_log_mgr(obj, log_type="info", regex=rex):
+        with stest.expect_exception_mgr(simics.SimExc_Attribute):
             obj.x_value = 42
 

test/1.4/lib/T_unmapped_access.dml

@@ -62,22 +62,22 @@ bank b {
 
 method init() {
     // Check regular register semantics
-    /// GREP \[obj spec-viol\] .*b.r1, bitranges;.*
+    /// GREP \[obj\.bank\.b spec-viol\] .*b.r1, bitranges;.*
     /// GREP .*15:0 .*written = 0b1111111111111111, previous.*= 0b0000111100001111.*
     b.r1.write_register(0xffffffff, 0xffffffff, NULL);
     // No log on second write
     b.r1.write_register(0xffffffff, 0xffffffff, NULL);
 
     // Check split ranges
-    /// GREP \[obj spec-viol\] .*b.r1, bitranges;.*
+    /// GREP \[obj\.bank\.b spec-viol\] .*b.r1, bitranges;.*
     /// GREP .*15:8 .*written = 0b11111111, previous.*= 0b00001111.*
     /// GREP .*3:0 .*written = 0b1111, previous.*= 0b0000.*
     b.r1_2.write_register(0xffffffff, 0x0000ff0f, NULL);
     b.r1_2.write_register(0xf0f0f0f0, 0xffffffff, NULL);
     assert b.r1_2.read_register(0xfffffff00, NULL) == 0xf0f0f000;
 
     // segmented by field bit range
-    /// GREP \[obj spec-viol\] .*b.r2, bitranges;.*
+    /// GREP \[obj\.bank\.b spec-viol\] .*b.r2, bitranges;.*
     /// GREP .*15:8 .*written = 0b11110000, previous.*= 0b00001111.*
     /// GREP .*3:0 .*written = 0b1111, previous.*= 0b0000.*
     b.r2.write_register(0x0f0f0f0f, 0xffffffff, NULL);