* [LTP] [PATCH] syscalls/acct02: Check read size.
@ 2019-09-25 9:47 Cyril Hrubis
2019-09-25 13:56 ` Petr Vorel
0 siblings, 1 reply; 15+ messages in thread
From: Cyril Hrubis @ 2019-09-25 9:47 UTC (permalink / raw)
To: ltp
This is just a minor adjustements that checks that we get correct size
from read before we attempt to validate the data we read in order to
print more meaningful failure message.
Signed-off-by: Cyril Hrubis <chrubis@suse.cz>
---
testcases/kernel/syscalls/acct/acct02.c | 16 ++++++++++++++--
1 file changed, 14 insertions(+), 2 deletions(-)
diff --git a/testcases/kernel/syscalls/acct/acct02.c b/testcases/kernel/syscalls/acct/acct02.c
index 110d99359..bdb7c1194 100644
--- a/testcases/kernel/syscalls/acct/acct02.c
+++ b/testcases/kernel/syscalls/acct/acct02.c
@@ -171,10 +171,21 @@ static void run(void)
acct(NULL);
do {
- tst_res(TINFO, "== entry %d ==", ++i);
-
read_bytes = SAFE_READ(0, fd, &acct_struct, acct_size);
+ if (i == 0 && read_bytes == 0) {
+ tst_res(TFAIL, "acct file is empty");
+ goto exit;
+ }
+
+ if (read_bytes != acct_size) {
+ tst_res(TFAIL, "incomplete read %i bytes, expected %i",
+ read_bytes, acct_size);
+ goto exit;
+ }
+
+ tst_res(TINFO, "== entry %d ==", ++i);
+
if (v3)
ret = verify_acct(&acct_struct.v3, acct_struct.v3.ac_etime);
else
@@ -192,6 +203,7 @@ static void run(void)
else
tst_res(TPASS, "acct() wrote correct file contents!");
+exit:
SAFE_CLOSE(fd);
}
--
2.21.0
^ permalink raw reply related [flat|nested] 15+ messages in thread
* [LTP] [PATCH] syscalls/acct02: Check read size.
2019-09-25 9:47 [LTP] [PATCH] syscalls/acct02: Check read size Cyril Hrubis
@ 2019-09-25 13:56 ` Petr Vorel
2019-09-25 16:14 ` Cyril Hrubis
` (2 more replies)
0 siblings, 3 replies; 15+ messages in thread
From: Petr Vorel @ 2019-09-25 13:56 UTC (permalink / raw)
To: ltp
Hi Cyril,
> This is just a minor adjustements that checks that we get correct size
> from read before we attempt to validate the data we read in order to
> print more meaningful failure message.
> Signed-off-by: Cyril Hrubis <chrubis@suse.cz>
Reviewed-by: Petr Vorel <pvorel@suse.cz>
> testcases/kernel/syscalls/acct/acct02.c | 16 ++++++++++++++--
...
> do {
> - tst_res(TINFO, "== entry %d ==", ++i);
> -
> read_bytes = SAFE_READ(0, fd, &acct_struct, acct_size);
> + if (i == 0 && read_bytes == 0) {
> + tst_res(TFAIL, "acct file is empty");
> + goto exit;
> + }
> +
> + if (read_bytes != acct_size) {
> + tst_res(TFAIL, "incomplete read %i bytes, expected %i",
> + read_bytes, acct_size);
> + goto exit;
> + }
> +
> + tst_res(TINFO, "== entry %d ==", ++i);
> +
> if (v3)
> ret = verify_acct(&acct_struct.v3, acct_struct.v3.ac_etime);
> else
> @@ -192,6 +203,7 @@ static void run(void)
> else
> tst_res(TPASS, "acct() wrote correct file contents!");
> +exit:
> SAFE_CLOSE(fd);
> }
OK, on s390 where it's failing it actually catches "incomplete read":
tst_kconfig.c:62: INFO: Parsing kernel config '/proc/config.gz'
tst_test.c:1118: INFO: Timeout per run is 0h 05m 00s
tst_kconfig.c:62: INFO: Parsing kernel config '/proc/config.gz'
acct02.c:234: INFO: Verifying using 'struct acct_v3'
acct02.c:187: INFO: == entry 1 ==
acct02.c:147: INFO: ac_version != 3 (131)
acct02.c:187: INFO: == entry 2 ==
acct02.c:82: INFO: ac_comm != 'acct02_helper' ('acct02')
acct02.c:133: INFO: ac_exitcode != 32768 (0)
acct02.c:141: INFO: ac_ppid != 54783 (54781)
acct02.c:147: INFO: ac_version != 3 (131)
acct02.c:183: FAIL: incomplete read 0 bytes, expected 64
Kind regards,
Petr
^ permalink raw reply [flat|nested] 15+ messages in thread
* [LTP] [PATCH] syscalls/acct02: Check read size.
2019-09-25 13:56 ` Petr Vorel
@ 2019-09-25 16:14 ` Cyril Hrubis
2019-09-27 11:38 ` Cyril Hrubis
2019-10-30 9:06 ` Jan Stancek
2 siblings, 0 replies; 15+ messages in thread
From: Cyril Hrubis @ 2019-09-25 16:14 UTC (permalink / raw)
To: ltp
Hi!
> > do {
> > - tst_res(TINFO, "== entry %d ==", ++i);
> > -
> > read_bytes = SAFE_READ(0, fd, &acct_struct, acct_size);
>
> > + if (i == 0 && read_bytes == 0) {
> > + tst_res(TFAIL, "acct file is empty");
> > + goto exit;
> > + }
> > +
> > + if (read_bytes != acct_size) {
> > + tst_res(TFAIL, "incomplete read %i bytes, expected %i",
> > + read_bytes, acct_size);
> > + goto exit;
> > + }
> > +
> > + tst_res(TINFO, "== entry %d ==", ++i);
> > +
> > if (v3)
> > ret = verify_acct(&acct_struct.v3, acct_struct.v3.ac_etime);
> > else
> > @@ -192,6 +203,7 @@ static void run(void)
> > else
> > tst_res(TPASS, "acct() wrote correct file contents!");
>
> > +exit:
> > SAFE_CLOSE(fd);
> > }
>
> OK, on s390 where it's failing it actually catches "incomplete read":
>
> tst_kconfig.c:62: INFO: Parsing kernel config '/proc/config.gz'
> tst_test.c:1118: INFO: Timeout per run is 0h 05m 00s
> tst_kconfig.c:62: INFO: Parsing kernel config '/proc/config.gz'
> acct02.c:234: INFO: Verifying using 'struct acct_v3'
> acct02.c:187: INFO: == entry 1 ==
> acct02.c:147: INFO: ac_version != 3 (131)
> acct02.c:187: INFO: == entry 2 ==
> acct02.c:82: INFO: ac_comm != 'acct02_helper' ('acct02')
> acct02.c:133: INFO: ac_exitcode != 32768 (0)
> acct02.c:141: INFO: ac_ppid != 54783 (54781)
> acct02.c:147: INFO: ac_version != 3 (131)
> acct02.c:183: FAIL: incomplete read 0 bytes, expected 64
Isn't that just end-of-file? I guess that we should just break the loop
if i != 0 and read returned 0.
--
Cyril Hrubis
chrubis@suse.cz
^ permalink raw reply [flat|nested] 15+ messages in thread
* [LTP] [PATCH] syscalls/acct02: Check read size.
2019-09-25 13:56 ` Petr Vorel
2019-09-25 16:14 ` Cyril Hrubis
@ 2019-09-27 11:38 ` Cyril Hrubis
2019-09-27 12:48 ` Petr Vorel
2019-10-30 9:06 ` Jan Stancek
2 siblings, 1 reply; 15+ messages in thread
From: Cyril Hrubis @ 2019-09-27 11:38 UTC (permalink / raw)
To: ltp
Hi!
I've just pushed this patch + one more special case for read_bytes == 0,
can you please give it a try and check that at least the test works
where it was working previously?
--
Cyril Hrubis
chrubis@suse.cz
^ permalink raw reply [flat|nested] 15+ messages in thread
* [LTP] [PATCH] syscalls/acct02: Check read size.
2019-09-27 11:38 ` Cyril Hrubis
@ 2019-09-27 12:48 ` Petr Vorel
0 siblings, 0 replies; 15+ messages in thread
From: Petr Vorel @ 2019-09-27 12:48 UTC (permalink / raw)
To: ltp
Hi Cyril,
> Hi!
> I've just pushed this patch + one more special case for read_bytes == 0,
> can you please give it a try and check that at least the test works
> where it was working previously?
Yep, confirm that it's working as expected :).
Kind regards,
Petr
^ permalink raw reply [flat|nested] 15+ messages in thread
* [LTP] [PATCH] syscalls/acct02: Check read size.
2019-09-25 13:56 ` Petr Vorel
2019-09-25 16:14 ` Cyril Hrubis
2019-09-27 11:38 ` Cyril Hrubis
@ 2019-10-30 9:06 ` Jan Stancek
2019-10-30 13:03 ` Jan Stancek
2 siblings, 1 reply; 15+ messages in thread
From: Jan Stancek @ 2019-10-30 9:06 UTC (permalink / raw)
To: ltp
----- Original Message -----
>
> OK, on s390 where it's failing it actually catches "incomplete read":
>
> tst_kconfig.c:62: INFO: Parsing kernel config '/proc/config.gz'
> tst_test.c:1118: INFO: Timeout per run is 0h 05m 00s
> tst_kconfig.c:62: INFO: Parsing kernel config '/proc/config.gz'
> acct02.c:234: INFO: Verifying using 'struct acct_v3'
> acct02.c:187: INFO: == entry 1 ==
> acct02.c:147: INFO: ac_version != 3 (131)
> acct02.c:187: INFO: == entry 2 ==
> acct02.c:82: INFO: ac_comm != 'acct02_helper' ('acct02')
> acct02.c:133: INFO: ac_exitcode != 32768 (0)
> acct02.c:141: INFO: ac_ppid != 54783 (54781)
> acct02.c:147: INFO: ac_version != 3 (131)
> acct02.c:183: FAIL: incomplete read 0 bytes, expected 64
I'm seeing similar failure:
tst_kconfig.c:62: INFO: Parsing kernel config '/boot/config-3.10.0-1106.el7.cki.s390x'
tst_test.c:1118: INFO: Timeout per run is 0h 05m 00s
tst_kconfig.c:62: INFO: Parsing kernel config '/boot/config-3.10.0-1106.el7.cki.s390x'
acct02.c:239: INFO: Verifying using 'struct acct_v3'
acct02.c:192: INFO: == entry 1 ==
acct02.c:88: INFO: ac_btime < 1572367954 (1572367953)
acct02.c:192: INFO: == entry 2 ==
acct02.c:82: INFO: ac_comm != 'acct02_helper' ('acct02')
acct02.c:88: INFO: ac_btime < 1572367954 (1572367953)
acct02.c:133: INFO: ac_exitcode != 32768 (0)
acct02.c:141: INFO: ac_ppid != 25608 (25607)
acct02.c:182: FAIL: end of file reached
but I don't get what process is this record from.
I see 3 pids: library, main and 'acct02_helper'. What 'acct02' process
terminated?
^ permalink raw reply [flat|nested] 15+ messages in thread
* [LTP] [PATCH] syscalls/acct02: Check read size.
2019-10-30 9:06 ` Jan Stancek
@ 2019-10-30 13:03 ` Jan Stancek
2019-10-30 14:46 ` Petr Vorel
0 siblings, 1 reply; 15+ messages in thread
From: Jan Stancek @ 2019-10-30 13:03 UTC (permalink / raw)
To: ltp
----- Original Message -----
>
>
> ----- Original Message -----
> >
> > OK, on s390 where it's failing it actually catches "incomplete read":
> >
> > tst_kconfig.c:62: INFO: Parsing kernel config '/proc/config.gz'
> > tst_test.c:1118: INFO: Timeout per run is 0h 05m 00s
> > tst_kconfig.c:62: INFO: Parsing kernel config '/proc/config.gz'
> > acct02.c:234: INFO: Verifying using 'struct acct_v3'
> > acct02.c:187: INFO: == entry 1 ==
> > acct02.c:147: INFO: ac_version != 3 (131)
> > acct02.c:187: INFO: == entry 2 ==
> > acct02.c:82: INFO: ac_comm != 'acct02_helper' ('acct02')
> > acct02.c:133: INFO: ac_exitcode != 32768 (0)
> > acct02.c:141: INFO: ac_ppid != 54783 (54781)
> > acct02.c:147: INFO: ac_version != 3 (131)
> > acct02.c:183: FAIL: incomplete read 0 bytes, expected 64
>
> I'm seeing similar failure:
>
> tst_kconfig.c:62: INFO: Parsing kernel config
> '/boot/config-3.10.0-1106.el7.cki.s390x'
> tst_test.c:1118: INFO: Timeout per run is 0h 05m 00s
> tst_kconfig.c:62: INFO: Parsing kernel config
> '/boot/config-3.10.0-1106.el7.cki.s390x'
> acct02.c:239: INFO: Verifying using 'struct acct_v3'
> acct02.c:192: INFO: == entry 1 ==
> acct02.c:88: INFO: ac_btime < 1572367954 (1572367953)
^^ This is 'acct02_helper', which seemingly started before 'start_time'.
ac_btime is calculated back from current time and elapsed time@fill_ac():
ac->ac_btime = get_seconds() - elapsed;
s390s are slower, so my guess is another second ticks before btime gets calculated,
and it appears to have started later.
> acct02.c:192: INFO: == entry 2 ==
> acct02.c:82: INFO: ac_comm != 'acct02_helper' ('acct02')
> acct02.c:88: INFO: ac_btime < 1572367954 (1572367953)
> acct02.c:133: INFO: ac_exitcode != 32768 (0)
> acct02.c:141: INFO: ac_ppid != 25608 (25607)
The 2nd record is filled at acct(NULL), even though process still runs:
[ 1156.025654] CPU: 0 PID: 11772 Comm: acct02_helper Tainted: G OE ------------ 3.10.0-1106.el7.s390x #1
<>
[ 1156.027105] [<00000000001dd630>] fill_ac+0x0/0x440
[ 1156.027108] ([<00000000001ddae8>] do_acct_process+0x78/0x1a0)
[ 1156.027110] [<00000000001de3ae>] acct_process+0xf6/0x140
[ 1156.027112] [<000000000014de32>] do_exit+0x752/0xa38
[ 1156.027116] [<000000000014e216>] do_group_exit+0x66/0xf8
[ 1156.027118] [<000000000014e2ea>] SyS_exit_group+0x42/0x48
[ 1157.033294] CPU: 1 PID: 11771 Comm: acct02 Tainted: G OE ------------ 3.10.0-1106.el7.s390x #1
<>
[ 1157.033384] [<00000000001dd630>] fill_ac+0x0/0x440
[ 1157.033386] ([<00000000001ddae8>] do_acct_process+0x78/0x1a0)
[ 1157.033389] [<00000000001ddcda>] acct_pin_kill+0x52/0xa8
[ 1157.033391] [<000000000034a83e>] pin_kill+0xb6/0x178
[ 1157.033395] [<00000000001ddfe8>] SyS_acct+0x2b8/0x350
^ permalink raw reply [flat|nested] 15+ messages in thread
* [LTP] [PATCH] syscalls/acct02: Check read size.
2019-10-30 13:03 ` Jan Stancek
@ 2019-10-30 14:46 ` Petr Vorel
2019-10-30 17:41 ` Jan Stancek
0 siblings, 1 reply; 15+ messages in thread
From: Petr Vorel @ 2019-10-30 14:46 UTC (permalink / raw)
To: ltp
Hi Jan,
> > I'm seeing similar failure:
> > tst_kconfig.c:62: INFO: Parsing kernel config
> > '/boot/config-3.10.0-1106.el7.cki.s390x'
> > tst_test.c:1118: INFO: Timeout per run is 0h 05m 00s
> > tst_kconfig.c:62: INFO: Parsing kernel config
> > '/boot/config-3.10.0-1106.el7.cki.s390x'
> > acct02.c:239: INFO: Verifying using 'struct acct_v3'
> > acct02.c:192: INFO: == entry 1 ==
> > acct02.c:88: INFO: ac_btime < 1572367954 (1572367953)
> ^^ This is 'acct02_helper', which seemingly started before 'start_time'.
> ac_btime is calculated back from current time and elapsed time at fill_ac():
> ac->ac_btime = get_seconds() - elapsed;
> s390s are slower, so my guess is another second ticks before btime gets calculated,
> and it appears to have started later.
Agree.
> > acct02.c:192: INFO: == entry 2 ==
> > acct02.c:82: INFO: ac_comm != 'acct02_helper' ('acct02')
> > acct02.c:88: INFO: ac_btime < 1572367954 (1572367953)
> > acct02.c:133: INFO: ac_exitcode != 32768 (0)
> > acct02.c:141: INFO: ac_ppid != 25608 (25607)
> The 2nd record is filled at acct(NULL), even though process still runs:
> [ 1156.025654] CPU: 0 PID: 11772 Comm: acct02_helper Tainted: G OE ------------ 3.10.0-1106.el7.s390x #1
> <>
> [ 1156.027105] [<00000000001dd630>] fill_ac+0x0/0x440
> [ 1156.027108] ([<00000000001ddae8>] do_acct_process+0x78/0x1a0)
> [ 1156.027110] [<00000000001de3ae>] acct_process+0xf6/0x140
> [ 1156.027112] [<000000000014de32>] do_exit+0x752/0xa38
> [ 1156.027116] [<000000000014e216>] do_group_exit+0x66/0xf8
> [ 1156.027118] [<000000000014e2ea>] SyS_exit_group+0x42/0x48
> [ 1157.033294] CPU: 1 PID: 11771 Comm: acct02 Tainted: G OE ------------ 3.10.0-1106.el7.s390x #1
> <>
> [ 1157.033384] [<00000000001dd630>] fill_ac+0x0/0x440
> [ 1157.033386] ([<00000000001ddae8>] do_acct_process+0x78/0x1a0)
> [ 1157.033389] [<00000000001ddcda>] acct_pin_kill+0x52/0xa8
> [ 1157.033391] [<000000000034a83e>] pin_kill+0xb6/0x178
> [ 1157.033395] [<00000000001ddfe8>] SyS_acct+0x2b8/0x350
Hm, did you reproduce it on 4.18 (rhel8)?
Kind regards,
Petr
^ permalink raw reply [flat|nested] 15+ messages in thread
* [LTP] [PATCH] syscalls/acct02: Check read size.
2019-10-30 14:46 ` Petr Vorel
@ 2019-10-30 17:41 ` Jan Stancek
2019-10-31 8:43 ` Li Wang
2019-10-31 9:06 ` Petr Vorel
0 siblings, 2 replies; 15+ messages in thread
From: Jan Stancek @ 2019-10-30 17:41 UTC (permalink / raw)
To: ltp
----- Original Message -----
> Hi Jan,
>
> > > I'm seeing similar failure:
>
> > > tst_kconfig.c:62: INFO: Parsing kernel config
> > > '/boot/config-3.10.0-1106.el7.cki.s390x'
> > > tst_test.c:1118: INFO: Timeout per run is 0h 05m 00s
> > > tst_kconfig.c:62: INFO: Parsing kernel config
> > > '/boot/config-3.10.0-1106.el7.cki.s390x'
> > > acct02.c:239: INFO: Verifying using 'struct acct_v3'
> > > acct02.c:192: INFO: == entry 1 ==
> > > acct02.c:88: INFO: ac_btime < 1572367954 (1572367953)
>
> > ^^ This is 'acct02_helper', which seemingly started before 'start_time'.
>
> > ac_btime is calculated back from current time and elapsed time at
> > fill_ac():
>
> > ac->ac_btime = get_seconds() - elapsed;
>
> > s390s are slower, so my guess is another second ticks before btime gets
> > calculated,
> > and it appears to have started later.
> Agree.
>
> > > acct02.c:192: INFO: == entry 2 ==
> > > acct02.c:82: INFO: ac_comm != 'acct02_helper' ('acct02')
> > > acct02.c:88: INFO: ac_btime < 1572367954 (1572367953)
> > > acct02.c:133: INFO: ac_exitcode != 32768 (0)
> > > acct02.c:141: INFO: ac_ppid != 25608 (25607)
>
> > The 2nd record is filled at acct(NULL), even though process still runs:
>
> > [ 1156.025654] CPU: 0 PID: 11772 Comm: acct02_helper Tainted: G
> > OE ------------ 3.10.0-1106.el7.s390x #1
> > <>
> > [ 1156.027105] [<00000000001dd630>] fill_ac+0x0/0x440
> > [ 1156.027108] ([<00000000001ddae8>] do_acct_process+0x78/0x1a0)
> > [ 1156.027110] [<00000000001de3ae>] acct_process+0xf6/0x140
> > [ 1156.027112] [<000000000014de32>] do_exit+0x752/0xa38
> > [ 1156.027116] [<000000000014e216>] do_group_exit+0x66/0xf8
> > [ 1156.027118] [<000000000014e2ea>] SyS_exit_group+0x42/0x48
>
> > [ 1157.033294] CPU: 1 PID: 11771 Comm: acct02 Tainted: G OE
> > ------------ 3.10.0-1106.el7.s390x #1
> > <>
> > [ 1157.033384] [<00000000001dd630>] fill_ac+0x0/0x440
> > [ 1157.033386] ([<00000000001ddae8>] do_acct_process+0x78/0x1a0)
> > [ 1157.033389] [<00000000001ddcda>] acct_pin_kill+0x52/0xa8
> > [ 1157.033391] [<000000000034a83e>] pin_kill+0xb6/0x178
> > [ 1157.033395] [<00000000001ddfe8>] SyS_acct+0x2b8/0x350
>
> Hm, did you reproduce it on 4.18 (rhel8)?
Above was RHEL7. Do you expect different outcome on RHEL8?
I was looking at upstream sources too and it looked similar.
Anyway, I don't think this part is an issue, test will skip it
because "comm" doesn't match.
We can tweak 'ac_btime' condition, but I think the test will remain
race-y in environments with higher steal time:
acct02.c:239: INFO: Verifying using 'struct acct_v3'
acct02.c:192: INFO: == entry 1 ==
acct02.c:127: INFO: elap_time/clock_ticks >= 2 (236/100: 2.00)
acct02.c:192: INFO: == entry 2 ==
acct02.c:82: INFO: ac_comm != 'acct02_helper' ('acct02')
acct02.c:127: INFO: elap_time/clock_ticks >= 2 (236/100: 2.00)
acct02.c:133: INFO: ac_exitcode != 32768 (0)
acct02.c:141: INFO: ac_ppid != 43213 (43212)
acct02.c:182: FAIL: end of file reached
^ permalink raw reply [flat|nested] 15+ messages in thread
* [LTP] [PATCH] syscalls/acct02: Check read size.
2019-10-30 17:41 ` Jan Stancek
@ 2019-10-31 8:43 ` Li Wang
2019-10-31 8:53 ` Jan Stancek
2019-10-31 9:06 ` Petr Vorel
1 sibling, 1 reply; 15+ messages in thread
From: Li Wang @ 2019-10-31 8:43 UTC (permalink / raw)
To: ltp
On Thu, Oct 31, 2019 at 1:41 AM Jan Stancek <jstancek@redhat.com> wrote:
>
>
> ----- Original Message -----
> > Hi Jan,
> >
> > > > I'm seeing similar failure:
> >
> > > > tst_kconfig.c:62: INFO: Parsing kernel config
> > > > '/boot/config-3.10.0-1106.el7.cki.s390x'
> > > > tst_test.c:1118: INFO: Timeout per run is 0h 05m 00s
> > > > tst_kconfig.c:62: INFO: Parsing kernel config
> > > > '/boot/config-3.10.0-1106.el7.cki.s390x'
> > > > acct02.c:239: INFO: Verifying using 'struct acct_v3'
> > > > acct02.c:192: INFO: == entry 1 ==
> > > > acct02.c:88: INFO: ac_btime < 1572367954 (1572367953)
> >
> > > ^^ This is 'acct02_helper', which seemingly started before
> 'start_time'.
> >
> > > ac_btime is calculated back from current time and elapsed time at
> > > fill_ac():
> >
> > > ac->ac_btime = get_seconds() - elapsed;
> >
> > > s390s are slower, so my guess is another second ticks before btime gets
> > > calculated,
> > > and it appears to have started later.
> > Agree.
> >
> > > > acct02.c:192: INFO: == entry 2 ==
> > > > acct02.c:82: INFO: ac_comm != 'acct02_helper' ('acct02')
> > > > acct02.c:88: INFO: ac_btime < 1572367954 (1572367953)
> > > > acct02.c:133: INFO: ac_exitcode != 32768 (0)
> > > > acct02.c:141: INFO: ac_ppid != 25608 (25607)
> >
> > > The 2nd record is filled at acct(NULL), even though process still runs:
> >
> > > [ 1156.025654] CPU: 0 PID: 11772 Comm: acct02_helper Tainted: G
> > > OE ------------ 3.10.0-1106.el7.s390x #1
> > > <>
> > > [ 1156.027105] [<00000000001dd630>] fill_ac+0x0/0x440
> > > [ 1156.027108] ([<00000000001ddae8>] do_acct_process+0x78/0x1a0)
> > > [ 1156.027110] [<00000000001de3ae>] acct_process+0xf6/0x140
> > > [ 1156.027112] [<000000000014de32>] do_exit+0x752/0xa38
> > > [ 1156.027116] [<000000000014e216>] do_group_exit+0x66/0xf8
> > > [ 1156.027118] [<000000000014e2ea>] SyS_exit_group+0x42/0x48
> >
> > > [ 1157.033294] CPU: 1 PID: 11771 Comm: acct02 Tainted: G OE
> > > ------------ 3.10.0-1106.el7.s390x #1
> > > <>
> > > [ 1157.033384] [<00000000001dd630>] fill_ac+0x0/0x440
> > > [ 1157.033386] ([<00000000001ddae8>] do_acct_process+0x78/0x1a0)
> > > [ 1157.033389] [<00000000001ddcda>] acct_pin_kill+0x52/0xa8
> > > [ 1157.033391] [<000000000034a83e>] pin_kill+0xb6/0x178
> > > [ 1157.033395] [<00000000001ddfe8>] SyS_acct+0x2b8/0x350
> >
> > Hm, did you reproduce it on 4.18 (rhel8)?
>
> Above was RHEL7. Do you expect different outcome on RHEL8?
> I was looking at upstream sources too and it looked similar.
>
> Anyway, I don't think this part is an issue, test will skip it
> because "comm" doesn't match.
>
> We can tweak 'ac_btime' condition, but I think the test will remain
>
How much time of the ac_btime shaking to be tolerated is proper?
> race-y in environments with higher steal time:
>
I'm sorry, what does it mean here?
>
> acct02.c:239: INFO: Verifying using 'struct acct_v3'
> acct02.c:192: INFO: == entry 1 ==
> acct02.c:127: INFO: elap_time/clock_ticks >= 2 (236/100: 2.00)
> acct02.c:192: INFO: == entry 2 ==
> acct02.c:82: INFO: ac_comm != 'acct02_helper' ('acct02')
> acct02.c:127: INFO: elap_time/clock_ticks >= 2 (236/100: 2.00)
> acct02.c:133: INFO: ac_exitcode != 32768 (0)
> acct02.c:141: INFO: ac_ppid != 43213 (43212)
> acct02.c:182: FAIL: end of file reached
>
>
> --
> Mailing list info: https://lists.linux.it/listinfo/ltp
>
--
Regards,
Li Wang
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.linux.it/pipermail/ltp/attachments/20191031/b174faa0/attachment.htm>
^ permalink raw reply [flat|nested] 15+ messages in thread
* [LTP] [PATCH] syscalls/acct02: Check read size.
2019-10-31 8:43 ` Li Wang
@ 2019-10-31 8:53 ` Jan Stancek
2019-10-31 9:09 ` Petr Vorel
2019-11-01 6:03 ` Li Wang
0 siblings, 2 replies; 15+ messages in thread
From: Jan Stancek @ 2019-10-31 8:53 UTC (permalink / raw)
To: ltp
----- Original Message -----
> > Above was RHEL7. Do you expect different outcome on RHEL8?
> > I was looking at upstream sources too and it looked similar.
> >
> > Anyway, I don't think this part is an issue, test will skip it
> > because "comm" doesn't match.
> >
> > We can tweak 'ac_btime' condition, but I think the test will remain
> >
>
> How much time of the ac_btime shaking to be tolerated is proper?
I wanted to go with 1 sec:
@@ -83,7 +83,7 @@ static int verify_acct(void *acc, int elap_time)
ret = 1;
}
- if (ACCT_MEMBER(ac_btime) < start_time) {
+ if (ACCT_MEMBER(ac_btime) + 1 < start_time) {
tst_res(TINFO, "ac_btime < %d (%d)", start_time,
ACCT_MEMBER(ac_btime));
ret = 1;
>
> > race-y in environments with higher steal time:
> >
>
> I'm sorry, what does it mean here?
I was referring to failed check below. s390 is scarce resource
and when over-committed, sleeps are less consistent.
E.g. sleep(1) taking 2+ seconds:
nanosleep({1, 0}, NULL) = 0 <1.926617>
>
>
>
> >
> > acct02.c:239: INFO: Verifying using 'struct acct_v3'
> > acct02.c:192: INFO: == entry 1 ==
> > acct02.c:127: INFO: elap_time/clock_ticks >= 2 (236/100: 2.00)
> > acct02.c:192: INFO: == entry 2 ==
> > acct02.c:82: INFO: ac_comm != 'acct02_helper' ('acct02')
> > acct02.c:127: INFO: elap_time/clock_ticks >= 2 (236/100: 2.00)
> > acct02.c:133: INFO: ac_exitcode != 32768 (0)
> > acct02.c:141: INFO: ac_ppid != 43213 (43212)
> > acct02.c:182: FAIL: end of file reached
^ permalink raw reply [flat|nested] 15+ messages in thread
* [LTP] [PATCH] syscalls/acct02: Check read size.
2019-10-30 17:41 ` Jan Stancek
2019-10-31 8:43 ` Li Wang
@ 2019-10-31 9:06 ` Petr Vorel
1 sibling, 0 replies; 15+ messages in thread
From: Petr Vorel @ 2019-10-31 9:06 UTC (permalink / raw)
To: ltp
Hi Jan,
> > Hm, did you reproduce it on 4.18 (rhel8)?
> Above was RHEL7. Do you expect different outcome on RHEL8?
> I was looking at upstream sources too and it looked similar.
I know it was RHEL7. Good it's not affected by old kernel code,
but rather by overloaded host. Agree, that some tolerance is needed.
> Anyway, I don't think this part is an issue, test will skip it
> because "comm" doesn't match.
> We can tweak 'ac_btime' condition, but I think the test will remain
> race-y in environments with higher steal time:
> acct02.c:239: INFO: Verifying using 'struct acct_v3'
> acct02.c:192: INFO: == entry 1 ==
> acct02.c:127: INFO: elap_time/clock_ticks >= 2 (236/100: 2.00)
> acct02.c:192: INFO: == entry 2 ==
> acct02.c:82: INFO: ac_comm != 'acct02_helper' ('acct02')
> acct02.c:127: INFO: elap_time/clock_ticks >= 2 (236/100: 2.00)
> acct02.c:133: INFO: ac_exitcode != 32768 (0)
> acct02.c:141: INFO: ac_ppid != 43213 (43212)
> acct02.c:182: FAIL: end of file reached
Kind regards,
Petr
^ permalink raw reply [flat|nested] 15+ messages in thread
* [LTP] [PATCH] syscalls/acct02: Check read size.
2019-10-31 8:53 ` Jan Stancek
@ 2019-10-31 9:09 ` Petr Vorel
2019-11-01 6:03 ` Li Wang
1 sibling, 0 replies; 15+ messages in thread
From: Petr Vorel @ 2019-10-31 9:09 UTC (permalink / raw)
To: ltp
Hi Jan,
> > How much time of the ac_btime shaking to be tolerated is proper?
> I wanted to go with 1 sec:
> @@ -83,7 +83,7 @@ static int verify_acct(void *acc, int elap_time)
> ret = 1;
> }
> - if (ACCT_MEMBER(ac_btime) < start_time) {
> + if (ACCT_MEMBER(ac_btime) + 1 < start_time) {
> tst_res(TINFO, "ac_btime < %d (%d)", start_time,
> ACCT_MEMBER(ac_btime));
> ret = 1;
Ack.
> > > race-y in environments with higher steal time:
> > I'm sorry, what does it mean here?
> I was referring to failed check below. s390 is scarce resource
> and when over-committed, sleeps are less consistent.
> E.g. sleep(1) taking 2+ seconds:
> nanosleep({1, 0}, NULL) = 0 <1.926617>
Lol :)
Kind regards,
Petr
^ permalink raw reply [flat|nested] 15+ messages in thread
* [LTP] [PATCH] syscalls/acct02: Check read size.
2019-10-31 8:53 ` Jan Stancek
2019-10-31 9:09 ` Petr Vorel
@ 2019-11-01 6:03 ` Li Wang
2019-11-01 8:54 ` Jan Stancek
1 sibling, 1 reply; 15+ messages in thread
From: Li Wang @ 2019-11-01 6:03 UTC (permalink / raw)
To: ltp
On Thu, Oct 31, 2019 at 4:53 PM Jan Stancek <jstancek@redhat.com> wrote:
>
> ----- Original Message -----
> > > Above was RHEL7. Do you expect different outcome on RHEL8?
> > > I was looking at upstream sources too and it looked similar.
> > >
> > > Anyway, I don't think this part is an issue, test will skip it
> > > because "comm" doesn't match.
> > >
> > > We can tweak 'ac_btime' condition, but I think the test will remain
> > >
> >
> > How much time of the ac_btime shaking to be tolerated is proper?
>
> I wanted to go with 1 sec:
>
I'm ok with that. Seems no better way so far.
>
> @@ -83,7 +83,7 @@ static int verify_acct(void *acc, int elap_time)
> ret = 1;
> }
>
> - if (ACCT_MEMBER(ac_btime) < start_time) {
> + if (ACCT_MEMBER(ac_btime) + 1 < start_time) {
> tst_res(TINFO, "ac_btime < %d (%d)", start_time,
> ACCT_MEMBER(ac_btime));
> ret = 1;
>
> >
> > > race-y in environments with higher steal time:
> > >
> >
> > I'm sorry, what does it mean here?
>
> I was referring to failed check below. s390 is scarce resource
> and when over-committed, sleeps are less consistent.
> E.g. sleep(1) taking 2+ seconds:
> nanosleep({1, 0}, NULL) = 0 <1.926617>
>
Okay.
>
> >
> >
> >
> > >
> > > acct02.c:239: INFO: Verifying using 'struct acct_v3'
> > > acct02.c:192: INFO: == entry 1 ==
> > > acct02.c:127: INFO: elap_time/clock_ticks >= 2 (236/100: 2.00)
> > > acct02.c:192: INFO: == entry 2 ==
> > > acct02.c:82: INFO: ac_comm != 'acct02_helper' ('acct02')
> > > acct02.c:127: INFO: elap_time/clock_ticks >= 2 (236/100: 2.00)
> > > acct02.c:133: INFO: ac_exitcode != 32768 (0)
> > > acct02.c:141: INFO: ac_ppid != 43213 (43212)
> > > acct02.c:182: FAIL: end of file reached
>
--
Regards,
Li Wang
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.linux.it/pipermail/ltp/attachments/20191101/eb7d8888/attachment.htm>
^ permalink raw reply [flat|nested] 15+ messages in thread
* [LTP] [PATCH] syscalls/acct02: Check read size.
2019-11-01 6:03 ` Li Wang
@ 2019-11-01 8:54 ` Jan Stancek
0 siblings, 0 replies; 15+ messages in thread
From: Jan Stancek @ 2019-11-01 8:54 UTC (permalink / raw)
To: ltp
----- Original Message -----
> On Thu, Oct 31, 2019 at 4:53 PM Jan Stancek <jstancek@redhat.com> wrote:
>
> >
> > ----- Original Message -----
> > > > Above was RHEL7. Do you expect different outcome on RHEL8?
> > > > I was looking at upstream sources too and it looked similar.
> > > >
> > > > Anyway, I don't think this part is an issue, test will skip it
> > > > because "comm" doesn't match.
> > > >
> > > > We can tweak 'ac_btime' condition, but I think the test will remain
> > > >
> > >
> > > How much time of the ac_btime shaking to be tolerated is proper?
> >
> > I wanted to go with 1 sec:
> >
>
> I'm ok with that. Seems no better way so far.
I want to look at this a bit more, and add some extra traces to kernel.
^ permalink raw reply [flat|nested] 15+ messages in thread
end of thread, other threads:[~2019-11-01 8:54 UTC | newest]
Thread overview: 15+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2019-09-25 9:47 [LTP] [PATCH] syscalls/acct02: Check read size Cyril Hrubis
2019-09-25 13:56 ` Petr Vorel
2019-09-25 16:14 ` Cyril Hrubis
2019-09-27 11:38 ` Cyril Hrubis
2019-09-27 12:48 ` Petr Vorel
2019-10-30 9:06 ` Jan Stancek
2019-10-30 13:03 ` Jan Stancek
2019-10-30 14:46 ` Petr Vorel
2019-10-30 17:41 ` Jan Stancek
2019-10-31 8:43 ` Li Wang
2019-10-31 8:53 ` Jan Stancek
2019-10-31 9:09 ` Petr Vorel
2019-11-01 6:03 ` Li Wang
2019-11-01 8:54 ` Jan Stancek
2019-10-31 9:06 ` Petr Vorel
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.