Bug 27465 - ERROR: Couldn't insert module&Invalid module format
Summary: ERROR: Couldn't insert module&Invalid module format
Status: RESOLVED OBSOLETE
Alias: None
Product: systemtap
Classification: Unclassified
Component: runtime (show other bugs)
Version: unspecified
: P2 normal
Target Milestone: ---
Assignee: Unassigned
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2021-02-25 02:13 UTC by lyeeer
Modified: 2024-02-21 13:07 UTC (History)
2 users (show)

See Also:
Host:
Target:
Build:
Last reconfirmed: 2021-03-02 00:00:00


Attachments
Execute script, used to get system calls of docker during execution (3.49 KB, text/x-matlab)
2021-02-25 02:13 UTC, lyeeer
Details
Module init trace (1.26 KB, text/plain)
2022-02-04 18:21 UTC, Vitaly Mayatskikh
Details

Note You need to log in before you can comment on or make changes to this bug.
Description lyeeer 2021-02-25 02:13:42 UTC
Created attachment 13262 [details]
Execute script, used to get system calls of docker during execution

Hello, When I use the systemTap4.4 version to test on an Ubuntu system with a kernel version of 4.4.0-21, the following problems occur.

ly@ubuntu:~/Desktop/LiCShield-master/LiCShield-master$ sudo stap -g /home/ly/Desktop/LiCShield-master/LiCShield-master/tracing_tool/systemtap_scripts/tracer.stp -DSTP_NO_OVERLOAD -DMAXSTRINGLEN=4096 -v -c /usr/bin/docker -d -o /home/ly/Desktop/LiCShield-master/LiCShield-master/training_session/python_build 

Pass 1: parsed user script and 480 library scripts using 124352virt/93704res/5424shr/88676data kb, in 340usr/100sys/434real ms. WARNING: confusing usage, consider @entry($file) in .return probe: identifier '$file' at /home/ly/Desktop/LiCShield-master/LiCShield-master/tracing_tool/systemtap_scripts/tracer.stp:380:43 source: path_arg[tid()] = get_path_wrapper(NULL, $file, %{ FILE %}) ^ WARNING: confusing usage, consider @entry($new_dir->mnt) in .return probe: identifier '$new_dir' at :391:30 source: old_path = get_path_wrapper($new_dir->mnt, $old_dentry, %{ DENTRY %}) ^ WARNING: confusing usage, consider @entry($old_dentry) in .return probe: identifier '$old_dentry' at :391:45 source: old_path = get_path_wrapper($new_dir->mnt, $old_dentry, %{ DENTRY %}) ^ WARNING: confusing usage, consider @entry($new_dir->mnt) in .return probe: identifier '$new_dir' at :392:29 source: path = get_path_wrapper($new_dir->mnt, $new_dentry, %{ DENTRY %}) ^ WARNING: confusing usage, consider @entry($new_dentry) in .return probe: identifier '$new_dentry' at :392:44 source: path = get_path_wrapper($new_dir->mnt, $new_dentry, %{ DENTRY %}) ^ WARNING: confusing usage, consider @entry($old_dir->mnt) in .return probe: identifier '$old_dir' at :406:30 source: old_path = get_path_wrapper($old_dir->mnt, $old_dentry, %{ DENTRY %}) ^ WARNING: confusing usage, consider @entry($old_dentry) in .return probe: identifier '$old_dentry' at :406:45 source: old_path = get_path_wrapper($old_dir->mnt, $old_dentry, %{ DENTRY %}) ^ WARNING: confusing usage, consider @entry($new_dir->mnt) in .return probe: identifier '$new_dir' at :407:29 source: path = get_path_wrapper($new_dir->mnt, $new_dentry, %{ DENTRY %}) ^ WARNING: confusing usage, consider @entry($new_dentry) in .return probe: identifier '$new_dentry' at :407:44 source: path = get_path_wrapper($new_dir->mnt, $new_dentry, %{ DENTRY %}) ^ WARNING: confusing usage, consider @entry($old_dentry) in .return probe: identifier '$old_dentry' at :411:19 source: if(is_dentry_dir($old_dentry)) ^ WARNING: confusing usage, consider @entry($path) in .return probe: identifier '$path' at :563:50 source: mount_target[tid] = get_path_wrapper(NULL, $path, %{ PATH %}) ^ WARNING: confusing usage, consider @entry($path) in .return probe: identifier '$path' at :567:47 source: mount_source[tid] = get_path_wrapper(NULL, $path, %{ PATH %}) ^ Pass 2: analyzed script: 34 probes, 33 functions, 100 embeds, 8 globals using 176924virt/147968res/6892shr/141248data kb, in 1170usr/860sys/2376real ms. WARNING: unused command line option $1/@1 
Pass 3: using cached /home/ly/.systemtap/cache/80/stap_80a92b209efe4091f63377f31abb085e_93148.c 
Pass 4: using cached /home/ly/.systemtap/cache/80/stap_80a92b209efe4091f63377f31abb085e_93148.ko 
Pass 5: starting run. ERROR: Couldn't insert module '/tmp/stapaon1yo/stap_80a92b209efe4091f63377f31abb085e_93148.ko': Invalid module format WARNING: /usr/local/bin/staprun exited with status: 1 
Pass 5: run completed in 0usr/0sys/2real ms. Pass 5: run failed. [man error::pass5]

Then, I searched for a related answer(Bug 24720) that said it was a problem with guru mode. But the C language code is embedded in my script, so I need to turn on the guru mode. If it is not turned on, an error will occur

ly@ubuntu:~/Desktop/LiCShield-master/LiCShield-master$ sudo stap /home/ly/Desktop/LiCShield-master/LiCShield-master/tracing_tool/systemtap_scripts/tracer.stp -v -c /usr/bin/docker -d -o /home/ly/Desktop/LiCShield-master/LiCShield-master/training_session/python_build parse error: embedded code in unprivileged script; need stap -g saw: embedded-code at /home/ly/Desktop/LiCShield-master/LiCShield-master/tracing_tool/systemtap_scripts/tracer.stp:1:1 source: ...
Comment 1 Frank Ch. Eigler 2021-03-02 20:14:33 UTC
dmesg might give further information about why the kernel rejected loading the systemtap module.   Can you try it again, and report what the kernel says?  Also,  increasing the pass-5 verbosity to a higher level may give us more tips.

# stap --vp 00004 ....
Comment 2 Vitaly Mayatskikh 2022-02-04 18:21:10 UTC
Created attachment 13957 [details]
Module init trace

Looks like it fails to resolve a symbol:

    74 insmod(34216):   ->find_symbol fsa=0xffffa1dc610c7d10
    76 insmod(34216):    ->find_exported_symbol_in_section syms=0xffffffffb2c288c0 owner=0x0 data=0xffffa1dc610c7d10
...
   103 insmod(34216):     ->cmp_name name=0xffffffffb2fcd7ee sym=0xffffffffb310b754
   104 insmod(34216):     <-cmp_name return=0x1
   105 insmod(34216):     ->cmp_name name=0xffffffffb2fcd7ee sym=0xffffffffb310b760
   106 insmod(34216):     <-cmp_name return=0x0
   107 insmod(34216):    <-find_exported_symbol_in_section return=0x1
   108 insmod(34216):   <-find_symbol return=0x1
   118 insmod(34216):  <-check_version return=0x0
   122 insmod(34216): <-load_module return=0xfffffffffffffff8
Comment 3 Frank Ch. Eigler 2022-02-04 18:23:11 UTC
It'd be helpful to see the last relevant lines of the output of dmesg.  Module loading related diagnostics are often printed there, to the kernel log.
Comment 4 Vitaly Mayatskikh 2022-02-04 18:53:32 UTC
Nothing in dmesg. After enabling pr_debug for kernel/modules.c I see only that:

[ 4686.786467] finit_module: fd=3, uargs=0000000066cecbb4, flags=0

Something is broken w.r.t. how Ubuntu's kernel is configured:

$ uname -v
#31~20.04.1-Ubuntu SMP Wed Jan 19 14:08:10 UTC 2022
Comment 5 Vitaly Mayatskikh 2022-02-04 19:22:02 UTC
check_version fails for module_layout:


   204 insmod(43808):   ->check_version info={.name="stap_30878", .mod=0xffffa1dc617d1740, .hdr=0xffffa1dc617c1000, .len=142104, .sechdrs=0xffffa1dc617e3098, .secstrings="", .strtab="", .symoffs=0, .stroffs=0, .init_typeoffs=0, .core_typeoffs=0, .debug=0x0, .num_debug=0, .sig_ok=0, .mod_kallsyms_init_off=0, .index={.sym=39, .str=40, .mod=34, .vers=0, .info=21, .pcpu=32}} symname="module_layout" crc=-1290631832 mod=ERROR
   207 insmod(43808):   <-check_version return=0x0

This is for non-guru case (does not fail):

   311 insmod(43893):   ->check_version info={.name="stap_11738", .mod=0xffffa1dc617d1c00, .hdr=0xffffa1dc617c1000, .len=139264, .sechdrs=0xffffa1dc617e2540, .secstrings="", .strtab="", .symoffs=0, .stroffs=0, .init_typeoffs=0, .core_typeoffs=0, .debug=0x0, .num_debug=0, .sig_ok=0, .mod_kallsyms_init_off=0, .index={.sym=40, .str=41, .mod=35, .vers=24, .info=21, .pcpu=33}} symname="module_layout" crc=-1290631832 mod=ERROR
   319 insmod(43893):   <-check_version return=0x1
Comment 6 Vitaly Mayatskikh 2022-02-04 19:30:30 UTC
check_version fails for module_layout:


   204 insmod(43808):   ->check_version info={.name="stap_30878", .mod=0xffffa1dc617d1740, .hdr=0xffffa1dc617c1000, .len=142104, .sechdrs=0xffffa1dc617e3098, .secstrings="", .strtab="", .symoffs=0, .stroffs=0, .init_typeoffs=0, .core_typeoffs=0, .debug=0x0, .num_debug=0, .sig_ok=0, .mod_kallsyms_init_off=0, .index={.sym=39, .str=40, .mod=34, .vers=0, .info=21, .pcpu=32}} symname="module_layout" crc=-1290631832 mod=ERROR
   207 insmod(43808):   <-check_version return=0x0

This is for non-guru case (does not fail):

   311 insmod(43893):   ->check_version info={.name="stap_11738", .mod=0xffffa1dc617d1c00, .hdr=0xffffa1dc617c1000, .len=139264, .sechdrs=0xffffa1dc617e2540, .secstrings="", .strtab="", .symoffs=0, .stroffs=0, .init_typeoffs=0, .core_typeoffs=0, .debug=0x0, .num_debug=0, .sig_ok=0, .mod_kallsyms_init_off=0, .index={.sym=40, .str=41, .mod=35, .vers=24, .info=21, .pcpu=33}} symname="module_layout" crc=-1290631832 mod=ERROR
   319 insmod(43893):   <-check_version return=0x1

____versions symbol is missing in the "broken" module:

$ sudo readelf -a /tmp/stapzTtc4M/stap_11738.ko | grep version
  [24] __versions        PROGBITS         0000000000000000  0000cc80
    27: 0000000000000076    35 OBJECT  LOCAL  DEFAULT   21 __UNIQUE_ID_srcversion127
    29: 0000000000000000  8832 OBJECT  LOCAL  DEFAULT   24 ____versions

$ sudo readelf -a /tmp/stapykqAs1/stap_30878.ko | grep version
    26: 00000000000000a3    35 OBJECT  LOCAL  DEFAULT   21 __UNIQUE_ID_srcversion127
Comment 7 Vitaly Mayatskikh 2022-02-04 19:40:31 UTC
check_version fails for module_layout:


   204 insmod(43808):   ->check_version info={.name="stap_30878", .mod=0xffffa1dc617d1740, .hdr=0xffffa1dc617c1000, .len=142104, .sechdrs=0xffffa1dc617e3098, .secstrings="", .strtab="", .symoffs=0, .stroffs=0, .init_typeoffs=0, .core_typeoffs=0, .debug=0x0, .num_debug=0, .sig_ok=0, .mod_kallsyms_init_off=0, .index={.sym=39, .str=40, .mod=34, .vers=0, .info=21, .pcpu=32}} symname="module_layout" crc=-1290631832 mod=ERROR
   207 insmod(43808):   <-check_version return=0x0

This is for non-guru case (does not fail):

   311 insmod(43893):   ->check_version info={.name="stap_11738", .mod=0xffffa1dc617d1c00, .hdr=0xffffa1dc617c1000, .len=139264, .sechdrs=0xffffa1dc617e2540, .secstrings="", .strtab="", .symoffs=0, .stroffs=0, .init_typeoffs=0, .core_typeoffs=0, .debug=0x0, .num_debug=0, .sig_ok=0, .mod_kallsyms_init_off=0, .index={.sym=40, .str=41, .mod=35, .vers=24, .info=21, .pcpu=33}} symname="module_layout" crc=-1290631832 mod=ERROR
   319 insmod(43893):   <-check_version return=0x1

____versions symbol is missing in the "broken" module:

$ sudo readelf -a /tmp/stapzTtc4M/stap_11738.ko | grep version
  [24] __versions        PROGBITS         0000000000000000  0000cc80
    27: 0000000000000076    35 OBJECT  LOCAL  DEFAULT   21 __UNIQUE_ID_srcversion127
    29: 0000000000000000  8832 OBJECT  LOCAL  DEFAULT   24 ____versions

$ sudo readelf -a /tmp/stapykqAs1/stap_30878.ko | grep version
    26: 00000000000000a3    35 OBJECT  LOCAL  DEFAULT   21 __UNIQUE_ID_srcversion127

Adding -B CONFIG_MODVERSIONS=y solved it for me. And this is where it gets messed up:

buildrun.cxx:
  // PR10280: suppress symbol versioning to restrict to exact kernel version
  //
  // XXX (PR24720): this was reported to cause problems on a PPC machine,
  // and I've spotted kernel commits (43e24e82f35) which vary the vermagic
  // string for PPC. Still, a standard PPC configuration tested fine, so
  // I'm cautiously re-enabling this.
  if (s.guru_mode)
    make_cmd.push_back("CONFIG_MODVERSIONS=");
  // Note: can re-enable from command line with "-B CONFIG_MODVERSIONS=y".
Comment 8 Frank Ch. Eigler 2022-02-09 23:57:47 UTC
modversion / module_layout checks tend to fail mainly if the system compiler used to build the kernel is different enough from the one used to build systemtap's kernel modules.  There are some gcc version-level features that vary the struct-module and other data types in linux, so modversions machinery can catch that.

I suggest checking compiler versions too.
Comment 9 Frank Ch. Eigler 2024-02-21 13:07:39 UTC
no recent investigation progress