Re: apparent bug about check_free_strict

Oops, Mail did create it using HTML, resending in plain text.



> On 18. Nov 2024, at 23:17, Toomas Soome <[email protected]> wrote:
>=20
>=20
>=20
>> On 18. Nov 2024, at 17:27, Dan Carpenter <[email protected]> =
wrote:
>>=20
>> On Mon, Nov 18, 2024 at 03:28:57PM +0200, Toomas Soome wrote:
>>>=20
>>>=20
>>>> On 18. Nov 2024, at 14:52, Dan Carpenter <[email protected]> =
wrote:
>>>>=20
>>>> On Mon, Nov 18, 2024 at 01:55:30PM +0200, Toomas Soome wrote:
>>>>> hi!
>>>>>=20
>>>>> I did enable illumos kernel memory allocation/free checks =
(kmem_alloc/kmem_free) and apparently I did find something interesting.
>>>>>=20
>>>>> The warning is:
>>>>> =
/code/illumos-gate/usr/src/tools/proto/root_i386-nd/opt/onbld/bin/i386/sma=
tch: ../../common/os/devcfg.c:8583 e_ddi_retire_device() warn: passing =
freed memory 'pdip'
>>>>> =
/code/illumos-gate/usr/src/tools/proto/root_i386-nd/opt/onbld/bin/i386/sma=
tch: ../../common/os/devcfg.c:8612 e_ddi_retire_device() warn: passing =
freed memory 'dip'
>>>>> =
/code/illumos-gate/usr/src/tools/proto/root_i386-nd/opt/onbld/bin/i386/sma=
tch: ../../common/os/devcfg.c:8621 e_ddi_retire_device() warn: passing =
freed memory =E2=80=98dip'
>>>>>=20
>>>>> The code for first error about pdip is:
>>>>>=20
>>>>> 8572          pdip =3D ddi_get_parent(dip);
>>>>> 8573          ndi_hold_devi(pdip);
>>>>> 8574     8575          /*
>>>>> 8576           * Run devfs_clean() in case dip has no constraints =
and is
>>>>> 8577           * not in use, so is retireable but there are =
dv_nodes holding
>>>>> 8578           * ref-count on the dip. Note that devfs_clean() =
always returns
>>>>> 8579           * success.
>>>>> 8580           */
>>>>> 8581          devnm =3D kmem_alloc(MAXNAMELEN + 1, KM_SLEEP);
>>>>> 8582          (void) ddi_deviname(dip, devnm);
>>>>> 8583          (void) devfs_clean(pdip, devnm + 1, DV_CLEAN_FORCE);
>>>>> 8584          kmem_free(devnm, MAXNAMELEN + 1);
>>>>> 8585     8586          ndi_devi_enter(pdip);
>>>>>=20
>>>>> We get this error about pdip with devfs_clean(), but apparently =
the =E2=80=98freed
>>>>> state is set with ndi_hold_devi(pdip) call; of course the call =
itself is not
>>>>> the quilty one, but the construct is =E2=80=94 as soon as I either =
comment the
>>>>> ndi_hold_devi() out *or* if I move it down before devfs_clean(), =
then
>>>>> the error disappears.
>>>>>=20
>>>>> Therefore, it appears that code segment such as:
>>>>>=20
>>>>> var =3D f();
>>>>> g(var);
>>>>>=20
>>>>> is causing state of var to be set =E2=80=98freed=E2=80=99 and =
check_free_strict.c is ending up
>>>>> spitting out the warning about passing freed memory with next =
function call.
>>>>>=20
>>>>=20
>>>> I don't see anything in ndi_hold_devi() which would mark "pdip" as =
freed.
>>>>=20
>>>=20
>>>=20
>>> As I wrote, I do not think it is really about the function itself, =
it is about
>>> the sequence =E2=80=94 when I moved the ndi_hold_devi() down just =
before the =E2=80=98pdip=E2=80=99 was actually called, then this warning =
did disappear.
>>>=20
>>>> I don't know how to run Smatch on this file...  Could you re-run =
Smatch with the
>>>> --debug=3D"free" option and save the output to a file?  Maybe send =
that output
>>>> along with the whole file or run it against the lates git so I can =
match the
>>>> line numbers up.
>>>>=20
>>>=20
>>> I guess it is a bit more complicated because you will also need the =
illumos specific update to check_free_strict.
>>>=20
>>> The command in usr/src/uts/intel/genunix is run as:
>>>=20
>>> =
/code/illumos-gate/usr/src/tools/proto/root_i386-nd/opt/onbld/bin/i386/sma=
tch --debug=3Dfree -fident -finline -fno-inline-functions -fno-builtin =
-fno-asm -fdiagnostics-show-option -nodefaultlibs -D__sun -m64 =
-mtune=3Dopteron -Ui386 -U__i386 -fno-strict-aliasing =
-fno-unit-at-a-time -fno-optimize-sibling-calls -O2 -D_ASM_INLINES =
-ffreestanding -mno-red-zone -mno-mmx -mno-sse -msave-args -Wall -Wextra =
-g -gdwarf-2 -std=3Dgnu99 -msave-args -Werror -Wno-missing-braces =
-Wno-sign-compare -Wno-unknown-pragmas -Wno-unused-parameter =
-Wno-missing-field-initializers -Winline -Wno-unused -Wno-empty-body =
-p=3Dillumos_kernel --disable=3Duninitialized,check_check_deref -Wno-vla =
-Wno-one-bit-signed-bitfield -Wno-external-function-has-definition =
-Wno-old-style-definition -Wno-strict-prototypes --fatal-checks =
--timeout=3D0 --disable=3Dindex_overflow =
--disable=3Dsigned,all_func_returns -Wno-unused-variable =
-Wno-unused-value -Wno-unused-function -Wno-parentheses =
-Wno-maybe-uninitialized -Wno-clobbered -Wno-empty-body =
-fno-inline-small-functions -fno-inline-functions-called-once =
-fno-ipa-cp -fno-ipa-icf -fno-clone-functions -fno-reorder-functions =
-fno-reorder-blocks-and-partition -fno-aggressive-loop-optimizations =
--param=3Dmax-inline-insns-single=3D450 -fno-shrink-wrap =
-mindirect-branch=3Dthunk-extern -mindirect-branch-register =
-fno-asynchronous-unwind-tables -fstack-protector-strong =
-fno-eliminate-unused-debug-symbols -fno-eliminate-unused-debug-types =
-D_KERNEL -ffreestanding -D_SYSCALL32 -D_SYSCALL32_IMPL -D_ELF64 =
-D_DDI_STRICT -Dsun -D__sun -D__SVR4 -DOPTERON_ERRATUM_88 =
-DOPTERON_ERRATUM_91 -DOPTERON_ERRATUM_93 -DOPTERON_ERRATUM_95 =
-DOPTERON_ERRATUM_99 -DOPTERON_ERRATUM_100 -DOPTERON_ERRATUM_101 =
-DOPTERON_ERRATUM_108 -DOPTERON_ERRATUM_109 -DOPTERON_ERRATUM_121 =
-DOPTERON_ERRATUM_122 -DOPTERON_ERRATUM_123 -DOPTERON_ERRATUM_131 =
-DOPTERON_WORKAROUND_6336786 -DOPTERON_ERRATUM_147 -DOPTERON_ERRATUM_172 =
-DOPTERON_ERRATUM_298 -DOPTERON_ERRATUM_721 -I../../intel -nostdinc =
-I../../common -I/code/illumos-gate/usr/src/common =
-I/code/illumos-gate/usr/src/uts/common/fs/zfs -I../../i86pc -c -o =
/tmp/cw.GCaq5P/cwICaO5P.o ../../common/os/devcfg.c -mcmodel=3Dkernel
>>>=20
>>>=20
>>> I did put the samples of files into =
http://132-104-190-90.sta.estpak.ee/smatch/,
>>> I still need to clean up a bit my smatch repo, that will take a bit =
more time.
>>>=20
>>=20
>> There's something weird going on.  I don't see any problem with the =
changes you
>> have made to check_free_strict.c.  I started to just merge your =
changes but then
>> I realized I don't know who to give authorship credit etc but I'd =
already pushed
>> whatever changes I had on my end so I just made the situation worse.
>>=20
>=20
> :D the kmem_alloc/kmem_free related bits are done by me. But we can =
sort later what we could and should upstream and what maybe not.
>=20
>> You are testing with the latest Smatch right?
>=20
>=20
> Yes. My current head of master branch is:
>=20
> commit 9a427ca57dc8a8b47d021f5f772ac164842bd996 (upstream/master, =
master)
> Author: Dan Carpenter <[email protected]>
> Date:   Thu Nov 14 23:12:46 2024 +0300
>=20
>     db: fix a NULL dereference in get_param()
>=20
>>=20
>> Anyway, I've attached the diff to the latest code below with some =
debugging.
>> Apply the diff to the lastest Smatch and apply the code-diff to the =
devcfg.c
>> and then re-run Smatch.
>>=20
>=20
> Now this is fun. With devcfg.c changes in place, the warnings =
disappeared. So I removed 'if (local_debug)=E2=80=99 from =
check_free_strict.c and, I think we have something to point to:
>=20
> =
/code/illumos-gate/usr/src/tools/proto/root_i386-nd/opt/onbld/bin/i386/sma=
tch: ../../common/os/devcfg.c:8573 e_ddi_retire_device() =
set_param_freed: expr=3D'ndi_hold_devi(pdip)' param=3D0 key=3D'$'
> =
/code/illumos-gate/usr/src/tools/proto/root_i386-nd/opt/onbld/bin/i386/sma=
tch: ../../common/os/devcfg.c:8573 e_ddi_retire_device() set_state new =
[check_free_strict] 'pdip' freed
> ../../common/os/devcfg.c:8573 e_ddi_retire_device() merge =
[check_free_strict] 'pdip' freed(L 8573) + undefined(L 8573) =3D> merged =
(freed, undefined, merged)
> =
/code/illumos-gate/usr/src/tools/proto/root_i386-nd/opt/onbld/bin/i386/sma=
tch: ../../common/os/devcfg.c:8573 e_ddi_retire_device() __set_sm new =
[check_free_strict] pdip fffff7ffe9523b90 =3D 'merged' [merged] (freed, =
undefined, merged)
> =
/code/illumos-gate/usr/src/tools/proto/root_i386-nd/opt/onbld/bin/i386/sma=
tch: ../../common/os/devcfg.c:8583 e_ddi_retire_device() warn: passing =
freed memory 'pdip'
>=20
> and the same for =E2=80=98dip=E2=80=99:
> =
/code/illumos-gate/usr/src/tools/proto/root_i386-nd/opt/onbld/bin/i386/sma=
tch: ../../common/os/devcfg.c:8611 e_ddi_retire_device() =
set_param_freed: expr=3D'is_leaf_node(dip)' param=3D0 key=3D'$'
> =
/code/illumos-gate/usr/src/tools/proto/root_i386-nd/opt/onbld/bin/i386/sma=
tch: ../../common/os/devcfg.c:8611 e_ddi_retire_device() set_state new =
[check_free_strict] 'dip=E2=80=99 freed
>=20
> and we will =
have:/code/illumos-gate/usr/src/tools/proto/root_i386-nd/opt/onbld/bin/i38=
6/smatch: ../../common/os/devcfg.c:8612 e_ddi_retire_device() warn: =
passing freed memory 'dip'
>=20
> So, set_param_freed() does register =E2=80=98pdip=E2=80=99 as freed, =
and this callback is set up as
>=20
> select_return_states_hook(PARAM_FREED, &set_param_freed);
>=20
> thanks,
> toomas


Hi!

I got some time to get back to this issue - yep, it is still present =
with current smatch. So I did use a bit of dtrace - I print out user =
space stack when we do enter set_param_freed(), and to verify the =
expression, I have this update:
 static void set_param_freed(struct expression *expr, int param, char =
*key, char *value)
 {
+       sm_msg("%s: expr=3D'%s' param=3D%d key=3D'%s'", __func__, =
expr_to_str(expr), param, key);
        set_param_helper(expr, param, key, value, &freed);
 }

it allows me to print out the expression with dtrace; the dtrace command =
line is there:

sudo dtrace -n 'pid$target::set_param_freed:entry { self->p =3D 1; =
ustack(); } pid$target::set_param_freed:return {self->p =3D 0;} =
pid$target::expr_to_str:return /self->p/ { printf("%s\n", =
copyinstr(arg1));}' -c =
'/code/illumos-gate/usr/src/tools/proto/root_i386-nd/opt/onbld/bin/i386/sm=
atch -fident -finline -fno-inline-functions -fno-builtin -fno-asm =
-fdiagnostics-show-option -nodefaultlibs -D__sun -m64 -mtune=3Dopteron =
-Ui386 -U__i386 -fno-strict-aliasing -fno-unit-at-a-time =
-fno-optimize-sibling-calls -O2 -D_ASM_INLINES -ffreestanding =
-mno-red-zone -mno-mmx -mno-sse -msave-args -Wall -Wextra -g -gdwarf-4 =
-gstrict-dwarf -std=3Dgnu99 -msave-args -Werror -Wno-missing-braces =
-Wno-sign-compare -Wno-unused-parameter -Wno-missing-field-initializers =
-Winline -Wno-unused -Wno-empty-body -p=3Dillumos_kernel =
--disable=3Duninitialized,check_check_deref -Wno-vla =
-Wno-one-bit-signed-bitfield -Wno-external-function-has-definition =
-Wno-old-style-definition -Wno-strict-prototypes --fatal-checks =
--timeout=3D0 --disable=3Dindex_overflow =
--disable=3Dsigned,all_func_returns -Wno-unused-variable =
-Wno-unused-value -Wno-unused-function -Wno-parentheses =
-Wno-maybe-uninitialized -Wno-clobbered -Wno-empty-body =
-fno-inline-small-functions -fno-inline-functions-called-once =
-fno-ipa-cp -fno-ipa-icf -fno-clone-functions -fno-reorder-functions =
-fno-reorder-blocks-and-partition -fno-aggressive-loop-optimizations =
--param=3Dmax-inline-insns-single=3D450 -fno-shrink-wrap =
-mindirect-branch=3Dthunk-extern -mindirect-branch-register =
-fno-asynchronous-unwind-tables -fstack-protector-strong =
-fno-eliminate-unused-debug-symbols -fno-eliminate-unused-debug-types =
-D_KERNEL -ffreestanding -D_SYSCALL32 -D_SYSCALL32_IMPL -D_ELF64 =
-D_DDI_STRICT -Dsun -D__sun -D__SVR4 -DOPTERON_ERRATUM_88 =
-DOPTERON_ERRATUM_91 -DOPTERON_ERRATUM_93 -DOPTERON_ERRATUM_95 =
-DOPTERON_ERRATUM_99 -DOPTERON_ERRATUM_100 -DOPTERON_ERRATUM_101 =
-DOPTERON_ERRATUM_108 -DOPTERON_ERRATUM_109 -DOPTERON_ERRATUM_121 =
-DOPTERON_ERRATUM_122 -DOPTERON_ERRATUM_123 -DOPTERON_ERRATUM_131 =
-DOPTERON_WORKAROUND_6336786 -DOPTERON_ERRATUM_147 -DOPTERON_ERRATUM_172 =
-DOPTERON_ERRATUM_298 -DOPTERON_ERRATUM_721 -I../../intel -nostdinc =
-I../../common -I/code/illumos-gate/usr/src/common =
-I/code/illumos-gate/usr/src/uts/common/fs/zfs -I../../i86pc -c -o =
/tmp/cwMia4d4.o ../../common/os/devcfg.c -mcmodel=3Dkernel=E2=80=99


and  for =E2=80=98pdip=E2=80=99 above, it did tell the user stack:

 10  87183            set_param_freed:entry=20
              smatch`set_param_freed
              smatch`call_db_return_callback+0x98
              smatch`db_return_states_callback+0x34c
              libsqlite3.so.3.50.4`sqlite3_exec+0x559
              smatch`sql_exec+0x1a1
              smatch`sql_select_return_states+0x15f
              smatch`db_return_states+0x9a
              smatch`db_return_states_call+0x59
              smatch`match_function_call+0x2e
              smatch`pass_expr_to_client+0x1f
              smatch`__pass_to_client+0xc8
              smatch`split_call+0x138
              smatch`__split_expr+0x4c5
              smatch`__split_stmt+0x335
              smatch`split_compound+0xca
              smatch`__split_stmt+0x346
              smatch`parse_fn_statements+0x24
              smatch`split_function+0x1c2
              smatch`split_c_file_functions+0x1d2
              smatch`smatch+0x17c

 10  87185               expr_to_str:return ndi_hold_devi(pdip)

 10  87185               expr_to_str:return pdip

Apparently we get =E2=80=98set_param_freed()=E2=80=99 called to mark =
=E2=80=9Cpdip=E2=80=9D freed from sql query, but we do not build sqllite =
db on disk - is it in memory db?

rgds,
toomas