APEI/ERST: Fix error message formatting

From: Borislav Petkov <[email protected]>

[    5.525861] ERST: Can not request iomem region <0x        c7eff000-0x        c7f00000> for ERST.

This needs to have leading zeroes. Make it so.

Signed-off-by Borislav Petkov <[email protected]>

Cc Anton Vorontsov <[email protected]>

Cc Colin Cross <[email protected]>

Cc Kees Cook <[email protected]>

Cc Tony Luck <[email protected]>

Cc Len Brown <[email protected]>

Cc "Rafael J. Wysocki" <[email protected]>

Cc [email protected]

Cc [email protected]

From: Borislav Petkov <[email protected]>

[    5.525861] ERST: Can not request iomem region <0x        c7eff000-0x        c7f00000> for ERST.

This needs to have leading zeroes. Make it so.

Signed-off-by Borislav Petkov <[email protected]>

Cc Anton Vorontsov <[email protected]>

Cc Colin Cross <[email protected]>

Cc Kees Cook <[email protected]>

Cc Tony Luck <[email protected]>

Cc Len Brown <[email protected]>

Cc "Rafael J. Wysocki" <[email protected]>

Cc [email protected]

Cc [email protected]

---
 drivers/acpi/apei/erst.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

drivers/acpi/apei/erst.c +0 -0

index 88d0b0f9f92b..1126afeb7e22 100644

Signature · 1 line

1.8.3

Quoted 5 lines · Borislav Petkov

From: Borislav Petkov <[email protected]>

[    5.525861] ERST: Can not request iomem region <0x        c7eff000-0x        c7f00000> for ERST.

This needs to have leading zeroes. Make it so.

While looking at this, I noticed that we seem to be using varying field widths in our APEI code:
- einj.c has two instances using %#010llx.
- apei-base.c uses widths of 10 (4 bytes) and 6 (2 bytes).

Not sure if these are intentional and those fields truly aren't 64-bit (as suggested by the usage of long long int).

Quoted 6 lines · Naveen N. Rao

Quoted 5 lines · Borislav Petkov

From: Borislav Petkov <[email protected]>

[    5.525861] ERST: Can not request iomem region <0x        c7eff000-0x        c7f00000> for ERST.

This needs to have leading zeroes. Make it so.

Why does it need leading zeros?

Quoted 5 lines

While looking at this, I noticed that we seem to be using varying field widths in our APEI code:
- einj.c has two instances using %#010llx.
- apei-base.c uses widths of 10 (4 bytes) and 6 (2 bytes).

Quoted 2 lines

Not sure if these are intentional and those fields truly aren't 64-bit (as suggested by the usage of long long int).

I suggest using "0x%llx" everywhere unless there's a compelling reason like columnar alignment for them.

That's an interesting question but I think you're better fitted to answer it - I try to avoid the APEI spec as much as possible.

:-)

Quoted 24 lines · Joe Perches

Quoted 9 lines · Naveen N. Rao

Quoted 7 lines · Borislav Petkov

From: Borislav Petkov <[email protected]>

[    5.525861] ERST: Can not request iomem region <0x        c7eff000-0x

c7f00000> for ERST.

This needs to have leading zeroes. Make it so.

Why does it need leading zeros?

Quoted 7 lines

While looking at this, I noticed that we seem to be using varying field widths in our APEI code:
- einj.c has two instances using %#010llx.
- apei-base.c uses widths of 10 (4 bytes) and 6 (2 bytes).

Not sure if these are intentional and those fields truly aren't 64-bit (as suggested by the usage of long long int).

Quoted 2 lines

I suggest using "0x%llx" everywhere unless there's a compelling reason like columnar alignment for them.

I think that might be better. I see that these changes were done in commit 46b91e37. Copying Bjorn Helgaas.

I would suggest a change similar to 46b91e37 for ERST, and I would suggest using the leading zeros, with %#010llx for physical memory addresses and %#06llx for ioport addresses. That's what %pR uses, and it produces columnar alignment in many cases (though not this one).

Quoted 4 lines · Bjorn Helgaas

I would suggest a change similar to 46b91e37 for ERST, and I would suggest using the leading zeros, with %#010llx for physical memory addresses and %#06llx for ioport addresses. That's what %pR uses, and it produces columnar alignment in many cases (though not this one).

How's that:

--
From: Borislav Petkov <[email protected]>
Date: Mon, 29 Jul 2013 15:51:35 +0200
Subject: [PATCH] [PATCH] APEI/ERST: Fix error message formatting

... according to acpi/apei/ conventions. Use standard pr_fmt prefix while at it.

Signed-off-by Borislav Petkov <[email protected]>

---
 drivers/acpi/apei/erst.c | 43 +++++++++++++++++++------------------------
 1 file changed, 19 insertions(+), 24 deletions(-)

drivers/acpi/apei/erst.c +3 -3

index 88d0b0f9f92b..853e4cf1bc9e 100644
@@ -39,7 +39,8 @@
 
 #include "apei-internal.h"
 
-#define ERST_PFX "ERST: "
+#undef pr_fmt
+#define pr_fmt(fmt) "ERST: " fmt
 
 /* ERST command status */
 #define ERST_STATUS_SUCCESS                    0x0

@@ -109,8 +110,7 @@ static inline int erst_errno(int command_status)
 static int erst_timedout(u64 *t, u64 spin_unit)
 {
        if ((s64)*t < spin_unit) {
-               pr_warning(FW_WARN ERST_PFX
-                          "Firmware does not respond in time\n");
+               pr_warn(FW_WARN "Firmware does not respond in time\n");
                return 1;
        }
        *t -= spin_unit;

drivers/acpi/apei/erst.c +9 -13

                                   ctx->value);
                stall_time = FIRMWARE_MAX_STALL;

@@ -206,7 +206,7 @@ static int erst_exec_stall_while_true(struct apei_exec_context *ctx,
 
        if (ctx->var1 > FIRMWARE_MAX_STALL) {
                if (!in_nmi())
-                       pr_warning(FW_WARN ERST_PFX
+                       pr_warn(FW_WARN
                "Too long stall time for stall while true instruction: %llx.\n",
                                   ctx->var1);
                stall_time = FIRMWARE_MAX_STALL;

@@ -271,8 +271,7 @@ static int erst_exec_move_data(struct apei_exec_context *ctx,
 
        /* ioremap does not work in interrupt context */
        if (in_interrupt()) {
-               pr_warning(ERST_PFX
-                          "MOVE_DATA can not be used in interrupt context");
+               pr_warn("MOVE_DATA can not be used in interrupt context");
                return -EBUSY;
        }
 

@@ -522,8 +521,7 @@ retry:
                                     ERST_RECORD_ID_CACHE_SIZE_MAX);
                if (new_size <= erst_record_id_cache.size) {
                        if (printk_ratelimit())
-                               pr_warning(FW_WARN ERST_PFX
-                                          "too many record ID!\n");
+                               pr_warn(FW_WARN "too many record IDs!\n");
                        return 0;
                }
                alloc_size = new_size * sizeof(entries[0]);

@@ -759,8 +757,7 @@ static int __erst_clear_from_storage(u64 record_id)
 static void pr_unimpl_nvram(void)
 {
        if (printk_ratelimit())
-               pr_warning(ERST_PFX
-               "NVRAM ERST Log Address Range is not implemented yet\n");
+               pr_warn("NVRAM ERST Log Address Range is not implemented yet\n");
 }
 
 static int __erst_write_to_nvram(const struct cper_record_header *record)

@@ -1120,7 +1117,7 @@ static int __init erst_init(void)
                goto err;
 
        if (erst_disable) {
-               pr_info(ERST_PFX
+               pr_info(
        "Error Record Serialization Table (ERST) support is disabled.\n");
                goto err;
        }

@@ -1131,14 +1128,14 @@ static int __init erst_init(void)
                goto err;
        else if (ACPI_FAILURE(status)) {
                const char *msg = acpi_format_exception(status);
-               pr_err(ERST_PFX "Failed to get table, %s\n", msg);
+               pr_err("Failed to get table, %s\n", msg);
                rc = -EINVAL;
                goto err;
        }
 
        rc = erst_check_table(erst_tab);
        if (rc) {
-               pr_err(FW_BUG ERST_PFX "ERST table is invalid\n");
+               pr_err(FW_BUG "ERST table is invalid\n");
                goto err;
        }
 

@@ -1156,21 +1153,19 @@ static int __init erst_init(void)
        rc = erst_get_erange(&erst_erange);
        if (rc) {
                if (rc == -ENODEV)
-                       pr_info(ERST_PFX
+                       pr_info(
        "The corresponding hardware device or firmware implementation "
        "is not available.\n");
                else
-                       pr_err(ERST_PFX
-                              "Failed to get Error Log Address Range.\n");
+                       pr_err("Failed to get Error Log Address Range.\n");
                goto err_unmap_reg;
        }

drivers/acpi/apei/erst.c +3 -4

                rc = -EIO;
                goto err_unmap_reg;
        }

@@ -1180,7 +1175,7 @@ static int __init erst_init(void)
        if (!erst_erange.vaddr)
                goto err_release_erange;
 
-       pr_info(ERST_PFX
+       pr_info(
        "Error Record Serialization Table (ERST) support is initialized.\n");
 
        buf = kmalloc(erst_erange.size, GFP_KERNEL);

@@ -1192,14 +1187,14 @@ static int __init erst_init(void)
                rc = pstore_register(&erst_info);
                if (rc) {
                        if (rc != -EPERM)
-                               pr_info(ERST_PFX
+                               pr_info(
                                "Could not register with persistent store\n");
                        erst_info.buf = NULL;
                        erst_info.bufsize = 0;
                        kfree(buf);
                }
        } else
-               pr_err(ERST_PFX
+               pr_err(
                "Failed to allocate %lld bytes for persistent store error log\n",
                erst_erange.size);
 
--

1.8.3

--
Regards/Gruss,
Boris.

Sent from a fat crate under my desk. Formatting is fine. --

drivers/acpi/apei/erst.c static int erst_exec_stall(struct apei_exec_context *ctx, · line 190

Quoted 7 lines

drivers/acpi/apei/erst.c +1 -1

@@ -186,7 +186,7 @@ static int erst_exec_stall(struct apei_exec_context *ctx,
 
        if (ctx->value > FIRMWARE_MAX_STALL) {
                if (!in_nmi())
-                       pr_warning(FW_WARN ERST_PFX
+                       pr_warn(FW_WARN
                        "Too long stall time for stall instruction: %llx.\n",

You didn't change this part, but this and similar messages look less useful than they could be. We're printing in hex, but there's no indication in the output (no "0x" prefix). And there's no instruction pointer or anything to help connect this back to the source of the problem.

Quoted 13 lines · Bjorn Helgaas

drivers/acpi/apei/erst.c static int erst_exec_stall(struct apei_exec_context *ctx, · line 190

Quoted 7 lines

drivers/acpi/apei/erst.c +1 -1

@@ -186,7 +186,7 @@ static int erst_exec_stall(struct apei_exec_context *ctx,
 
        if (ctx->value > FIRMWARE_MAX_STALL) {
                if (!in_nmi())
-                       pr_warning(FW_WARN ERST_PFX
+                       pr_warn(FW_WARN
                        "Too long stall time for stall instruction: %llx.\n",

You didn't change this part, but this and similar messages look less useful than they could be. We're printing in hex, but there's no indication in the output (no "0x" prefix). And there's no instruction pointer or anything to help connect this back to the source of the problem.

Sounds like we don't want to print ctx->value at all but simply signal about the stall? Or?

If I were the firmware developer and got a report about this message, I think the information I would want is ctx->ip, so I could identify the corresponding source code. But I don't know much about the ERST interpreter, so I don't know if "ctx->ip" is the right place to look.

Maybe there's a method name or table name that would be needed in addition.

It just seems like "ERST: Too long stall time for stall instruction:
4732." all by itself doesn't really contain any actionable information.

Right, I'll make it be a hex "0x" in both stall-functions and leave it to someone more ACPI-knowledgeable to decide what goes in there - my patch is a simple cleanup anyway.

From: Borislav Petkov <[email protected]>

Quoted 4 lines · Bjorn Helgaas

If I were the firmware developer and got a report about this message, I think the information I would want is ctx->ip, so I could identify the corresponding source code. But I don't know much about the ERST interpreter, so I don't know if "ctx->ip" is the right place to look.

Well, __apei_exec_run() really does update ctx->ip when executing actions but if you read the comment in that function, it says it actually points to the next RIP to be executed. Which is not what we want in that case, IMO.

Quoted 3 lines

Maybe there's a method name or table name that would be needed in addition.

Quoted 3 lines

It just seems like "ERST: Too long stall time for stall instruction:
4732." all by itself doesn't really contain any actionable information.

Right, I'll make it be a hex "0x" in both stall-functions and leave it to someone more ACPI-knowledgeable to decide what goes in there - my patch is a simple cleanup anyway.

Here's an updated version:

---
From: Borislav Petkov <[email protected]>
Date: Mon, 29 Jul 2013 15:51:35 +0200
Subject: [PATCH] [PATCH] APEI/ERST: Fix error message formatting

... according to acpi/apei/ conventions. Use standard pr_fmt prefix while at it.

Also, make add the "0x" prefix to the stalled instruction functions error path and make the iomem region closed on both ends.

Signed-off-by Borislav Petkov <[email protected]>

---
 drivers/acpi/apei/erst.c | 47 +++++++++++++++++++++--------------------------
 1 file changed, 21 insertions(+), 26 deletions(-)

drivers/acpi/apei/erst.c +21 -27

index 88d0b0f9f92b..4e342692d304 100644
@@ -39,7 +39,8 @@
 
 #include "apei-internal.h"
 
-#define ERST_PFX "ERST: "
+#undef pr_fmt
+#define pr_fmt(fmt) "ERST: " fmt
 
 /* ERST command status */
 #define ERST_STATUS_SUCCESS                    0x0

@@ -109,8 +110,7 @@ static inline int erst_errno(int command_status)
 static int erst_timedout(u64 *t, u64 spin_unit)
 {
        if ((s64)*t < spin_unit) {
-               pr_warning(FW_WARN ERST_PFX
-                          "Firmware does not respond in time\n");
+               pr_warn(FW_WARN "Firmware does not respond in time\n");
                return 1;
        }
        *t -= spin_unit;

@@ -186,8 +186,8 @@ static int erst_exec_stall(struct apei_exec_context *ctx,
 
        if (ctx->value > FIRMWARE_MAX_STALL) {
                if (!in_nmi())
-                       pr_warning(FW_WARN ERST_PFX
-                       "Too long stall time for stall instruction: %llx.\n",
+                       pr_warn(FW_WARN
+                       "Too long stall time for stall instruction: 0x%llx.\n",
                                   ctx->value);
                stall_time = FIRMWARE_MAX_STALL;
        } else

@@ -206,8 +206,8 @@ static int erst_exec_stall_while_true(struct apei_exec_context *ctx,
 
        if (ctx->var1 > FIRMWARE_MAX_STALL) {
                if (!in_nmi())
-                       pr_warning(FW_WARN ERST_PFX
-               "Too long stall time for stall while true instruction: %llx.\n",
+                       pr_warn(FW_WARN
+               "Too long stall time for stall while true instruction: 0x%llx.\n",
                                   ctx->var1);
                stall_time = FIRMWARE_MAX_STALL;
        } else

@@ -271,8 +271,7 @@ static int erst_exec_move_data(struct apei_exec_context *ctx,
 
        /* ioremap does not work in interrupt context */
        if (in_interrupt()) {
-               pr_warning(ERST_PFX
-                          "MOVE_DATA can not be used in interrupt context");
+               pr_warn("MOVE_DATA can not be used in interrupt context");
                return -EBUSY;
        }
 

@@ -522,8 +521,7 @@ retry:
                                     ERST_RECORD_ID_CACHE_SIZE_MAX);
                if (new_size <= erst_record_id_cache.size) {
                        if (printk_ratelimit())
-                               pr_warning(FW_WARN ERST_PFX
-                                          "too many record ID!\n");
+                               pr_warn(FW_WARN "too many record IDs!\n");
                        return 0;
                }
                alloc_size = new_size * sizeof(entries[0]);

@@ -759,8 +757,7 @@ static int __erst_clear_from_storage(u64 record_id)
 static void pr_unimpl_nvram(void)
 {
        if (printk_ratelimit())
-               pr_warning(ERST_PFX
-               "NVRAM ERST Log Address Range is not implemented yet\n");
+               pr_warn("NVRAM ERST Log Address Range is not implemented yet\n");
 }
 
 static int __erst_write_to_nvram(const struct cper_record_header *record)

@@ -1120,7 +1117,7 @@ static int __init erst_init(void)
                goto err;
 
        if (erst_disable) {
-               pr_info(ERST_PFX
+               pr_info(
        "Error Record Serialization Table (ERST) support is disabled.\n");
                goto err;
        }

@@ -1131,14 +1128,14 @@ static int __init erst_init(void)
                goto err;
        else if (ACPI_FAILURE(status)) {
                const char *msg = acpi_format_exception(status);
-               pr_err(ERST_PFX "Failed to get table, %s\n", msg);
+               pr_err("Failed to get table, %s\n", msg);
                rc = -EINVAL;
                goto err;
        }
 
        rc = erst_check_table(erst_tab);
        if (rc) {
-               pr_err(FW_BUG ERST_PFX "ERST table is invalid\n");
+               pr_err(FW_BUG "ERST table is invalid\n");
                goto err;
        }
 

@@ -1156,21 +1153,19 @@ static int __init erst_init(void)
        rc = erst_get_erange(&erst_erange);
        if (rc) {
                if (rc == -ENODEV)
-                       pr_info(ERST_PFX
+                       pr_info(
        "The corresponding hardware device or firmware implementation "
        "is not available.\n");
                else
-                       pr_err(ERST_PFX
-                              "Failed to get Error Log Address Range.\n");
+                       pr_err("Failed to get Error Log Address Range.\n");
                goto err_unmap_reg;
        }
 
        r = request_mem_region(erst_erange.base, erst_erange.size, "APEI ERST");
        if (!r) {
-               pr_err(ERST_PFX
-               "Can not request iomem region <0x%16llx-0x%16llx> for ERST.\n",
-               (unsigned long long)erst_erange.base,
-               (unsigned long long)erst_erange.base + erst_erange.size);
+               pr_err("Can not request [mem %#010llx-%#010llx] for ERST.\n",
+                      (unsigned long long)erst_erange.base,
+                      (unsigned long long)erst_erange.base + erst_erange.size - 1);
                rc = -EIO;
                goto err_unmap_reg;
        }

@@ -1180,7 +1175,7 @@ static int __init erst_init(void)
        if (!erst_erange.vaddr)
                goto err_release_erange;
 
-       pr_info(ERST_PFX
+       pr_info(
        "Error Record Serialization Table (ERST) support is initialized.\n");
 
        buf = kmalloc(erst_erange.size, GFP_KERNEL);

@@ -1192,14 +1187,14 @@ static int __init erst_init(void)
                rc = pstore_register(&erst_info);
                if (rc) {
                        if (rc != -EPERM)
-                               pr_info(ERST_PFX
+                               pr_info(
                                "Could not register with persistent store\n");
                        erst_info.buf = NULL;
                        erst_info.bufsize = 0;
                        kfree(buf);
                }
        } else
-               pr_err(ERST_PFX
+               pr_err(
                "Failed to allocate %lld bytes for persistent store error log\n",
                erst_erange.size);
 
--

1.8.3

--
Regards/Gruss,
Boris.

Sent from a fat crate under my desk. Formatting is fine. --

Yep, fair enough. Looks good to me.

Quoted 29 lines · Naveen N. Rao

Quoted 26 lines · Joe Perches

Quoted 9 lines · Naveen N. Rao

Quoted 7 lines · Borislav Petkov

From: Borislav Petkov <[email protected]>

[    5.525861] ERST: Can not request iomem region <0x        c7eff000-0x

c7f00000> for ERST.

This needs to have leading zeroes. Make it so.

Why does it need leading zeros?

Quoted 7 lines

While looking at this, I noticed that we seem to be using varying field widths in our APEI code:
- einj.c has two instances using %#010llx.
- apei-base.c uses widths of 10 (4 bytes) and 6 (2 bytes).

Not sure if these are intentional and those fields truly aren't 64-bit (as suggested by the usage of long long int).

I suggest using "0x%llx" everywhere unless there's a compelling reason like columnar alignment for them.

Quoted 2 lines

I think that might be better. I see that these changes were done in commit 46b91e37. Copying Bjorn Helgaas.

As the 46b91e37 changelog says, it was done to use "the normal %pR-like format". I think that's a valid goal. When we're printing the same sort of information, we should use the same sort of format.

But I don't think the "Can not request iomem region <0x
c7eff000-0x c7f00000> for ERST" output mentioned in the
original post was affected by 46b91e37. I would suggest a change similar to 46b91e37 for ERST, and I would suggest using the leading zeros, with %#010llx for physical memory addresses and %#06llx for ioport addresses. That's what %pR uses, and it produces columnar alignment in many cases (though not this one).

Bjorn

My key question was about why we are using a field width of 10 implying a 32-bit value, rather than a field width of 18 as suggested by the data type? This shouldn't truncate the value, but if we are specifying the field width for alignment, seems to me it is better to match the data type.

Quoted 4 lines · Naveen N. Rao

My key question was about why we are using a field width of 10 implying a 32-bit value, rather than a field width of 18 as suggested by the data type? This shouldn't truncate the value, but if we are specifying the field width for alignment, seems to me it is better to match the data type.

%pR uses a field width of 10 (two for "0x", eight for the value) simply because the majority of resource values fit in 32 bits. Larger values extend the width, so it's not a question of truncating any data. But it's no fun to read memory addresses when most of them have eight extra leading zeros (the high 32-bits of a 64-bit value). I think the same applies here; most ACPI table addresses still fit in 32 bits.

We *do* use a field width of 18 for the e820 table, even though many of those regions fit in 32 bits. But that's sort of an exception because it's a table where addresses above 4GB are pretty common.

But at the end of the day, I guess I'm just stating my personal preferences and yours might be different.

While looking at this, I noticed that we seem to be using varying field widths in our APEI code: - einj.c has two instances using %#010llx. - apei-base.c uses widths of 10 (4 bytes) and 6 (2 bytes).

Not sure if these are intentional and those fields truly aren't 64-bit (as suggested by the usage of long long int).