[LU-4483] sanity test 133f: Panic Created: 14/Jan/14 Updated: 23/Dec/15 Resolved: 23/Dec/14 |
|
| Status: | Resolved |
| Project: | Lustre |
| Component/s: | None |
| Affects Version/s: | Lustre 2.6.0 |
| Fix Version/s: | Lustre 2.6.0 |
| Type: | Bug | Priority: | Critical |
| Reporter: | Alexey Lyashkov | Assignee: | WC Triage |
| Resolution: | Fixed | Votes: | 0 |
| Labels: | None | ||
| Environment: |
OSTCOUNT=40 sh sanity.sh |
||
| Issue Links: |
|
||||||||||||
| Severity: | 3 | ||||||||||||
| Rank (Obsolete): | 12274 | ||||||||||||
| Description |
|
Lustre: DEBUG MARKER: == sanity test 133f: Check for LBUGs/Oopses/unreadable files in /proc == 13:22:32 (1389691352) Pid: 35, comm: events/0 Tainted: G --------------- T 2.6.32-358.18.1-lustre #0 VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform |
| Comments |
| Comment by James A Simmons [ 14/Jan/14 ] |
|
Somebody is attempting to read data using too little memory using a non seq_file read routine. If this started to just happen it might be NRS tbf or nodemap. Since it crashed on a list_del I only see NRS tbf working with list. Can you post a link to the maloo test that failed so I can see which proc entry is the source of the problem. |
| Comment by Alexey Lyashkov [ 14/Jan/14 ] |
|
James, it's may local sanity.sh run. console output: cat: /proc/fs/lustre/osc/lustre-OST0005-osc-ffff8800aff251b8/ping: Input/output error cat: /proc/fs/lustre/osc/lustre-OST0004-osc-ffff8800aff251b8/ping: Input/output error cat: /proc/fs/lustre/osc/lustre-OST0003-osc-ffff8800aff251b8/ping: Input/output error cat: /proc/fs/lustre/osc/lustre-OST0002-osc-ffff8800aff251b8/ping: Input/output error cat: /proc/fs/lustre/osc/lustre-OST0001-osc-ffff8800aff251b8/ping: Input/output error cat: /proc/fs/lustre/osc/lustre-OST0000-osc-ffff8800aff251b8/ping: Input/output error cat: /proc/fs/lustre/mdc/lustre-MDT0000-mdc-ffff8800aff251b8/ping: Input/output error cat: /proc/fs/lustre/fld/cli-lustre-clilmv-ffff8800aff251b8/cache_flush: Input/output error Timeout, server 192.168.69.5 not responding. berloga-mac:~ shadow$ from my point view - it's memory corruption issue - when someone overwrite an slab's internal list. |
| Comment by Andreas Dilger [ 15/Jan/14 ] |
|
Shadow, it would be great if you could include "git describe" output with your bug reports, so we can see what version of the code you are running. James, will the /proc file in question be moved over to seq_file with your patches? Do you know which patch covers this /proc file, and has it landed yet? |
| Comment by James A Simmons [ 15/Jan/14 ] |
|
The output Alexey is seeing for the the sanity test is normal. Both ping and cache_flush are write only so reading will give a error. In the past you could perform a read on a write proc entry. Now the LBUG is not normal. Can you send me your dmesg and lustre debug logs. I like to see which proc entry is exactly crashing. I don't know if the above proc entries are the real problem. |
| Comment by James A Simmons [ 16/Jan/14 ] |
|
Today I looked to see why a test for readable proc file was selecting write only enrty. It appears to be find -readable option still selects write only files. When I used -perm 444 I had no problems. I can't reproduce the Oops you saw so far. This is testing with a unpatched copy of the lastest master from this morning. |
| Comment by Alexey Lyashkov [ 16/Jan/14 ] |
|
James, it's not a LBUG (aka lustre bug) it's just found a list corruption. did you run own tests with kernel with debug options enabled? I have all debug options enabled. |
| Comment by Alexey Lyashkov [ 16/Jan/14 ] |
|
replicated again [root@rhel6-64 tests]# OSTCOUNT=40 ONLY=133 REFORMAT=yes sh sanity.sh
Logging to shared log directory: /tmp/test_logs/1389900285
== sanity test 133e: Verifying OST {read,write}_bytes nid stats =================== 23:26:08 (1389900368)
42+0 records in
42+0 records out
1376256 bytes (1.4 MB) copied, 0.0373407 s, 36.9 MB/s
sanity test_133e: @@@@@@ FAIL: Bad write_bytes sum, expected 1376256, got 0
Trace dump:
= /Users/shadow/work/lustre/work/WC-review/CLSTR-2003/lustre/tests/test-framework.sh:4430:error_noexit()
= /Users/shadow/work/lustre/work/WC-review/CLSTR-2003/lustre/tests/test-framework.sh:4461:error()
= sanity.sh:8714:test_133e()
= /Users/shadow/work/lustre/work/WC-review/CLSTR-2003/lustre/tests/test-framework.sh:4701:run_one()
= /Users/shadow/work/lustre/work/WC-review/CLSTR-2003/lustre/tests/test-framework.sh:4736:run_one_logged()
= /Users/shadow/work/lustre/work/WC-review/CLSTR-2003/lustre/tests/test-framework.sh:4562:run_test()
= sanity.sh:8720:main()
Dumping lctl log to /tmp/test_logs/1389900285/sanity.test_133e.*.1389900369.log
Dumping logs only on local client.
FAIL 133e (25s)
== sanity test 133f: Check for LBUGs/Oopses/unreadable files in /proc == 23:26:33 (1389900393)
Timeout, server 192.168.69.5 not responding.
console output LustreError: Skipped 3513 previous similar messages LustreError: 685:0:(ldlm_resource.c:1154:ldlm_resource_get()) lustre-OST001e: lvbo_init failed for resource 0x43:0x0: rc = -2 LustreError: 685:0:(ldlm_resource.c:1154:ldlm_resource_get()) Skipped 6505 previous similar messages LustreError: 11-0: lustre-OST0018-osc-ffff88008357c488: Communicating with 0@lo, operation ldlm_enqueue failed with -12. LustreError: Skipped 6484 previous similar messages Lustre: DEBUG MARKER: == sanity test 133e: Verifying OST read_bytes write_bytes nid stats =================== 23:26:08 (1389900368) Lustre: DEBUG MARKER: cancel_lru_locks osc start Lustre: DEBUG MARKER: cancel_lru_locks osc stop Lustre: DEBUG MARKER: cancel_lru_locks osc start Lustre: DEBUG MARKER: cancel_lru_locks osc stop Lustre: DEBUG MARKER: sanity test_133e: @@@@@@ FAIL: Bad write_bytes sum, expected 1376256, got 0 Lustre: DEBUG MARKER: == sanity test 133f: Check for LBUGs/Oopses/unreadable files in /proc == 23:26:33 (1389900393) proc_file_read: Apparent buffer overflow! proc_file_read: Apparent buffer overflow! proc_file_read: Apparent buffer overflow! general protection fault: 0000 [#1] SMP last sysfs file: /sys/devices/system/cpu/online CPU 3 Modules linked in: lustre ofd osp lod ost mdt mdd mgs nodemap osd_ldiskfs ldiskfs lquota lfsck obdecho mgc lov osc mdc lmv fid fld ptlrpc obdclass ksocklnd lnet libcfs exportfs jb d sha512_generic sha256_generic crc32c_intel nfs lockd auth_rpcgss nfs_acl sunrpc cachefiles fscache(T) ib_ipoib ib_cm ipv6 ib_uverbs ib_umad mlx4_ib ib_sa ib_mad ib_core mlx4_en mlx4_core dm_mirror dm_region_hash dm_log dm_mod ppdev parport_pc parport microcode vmware_balloon vmxnet3 sg i2c_piix4 i2c_core shpchp ext4 jbd2 mbcache sd_mod crc_t10dif sr_mod cdrom vmw_pvscsi pata_acpi ata_generic ata_piix [last unloaded: libcfs] Pid: 1727, comm: vmmemctl Tainted: G --------------- T 2.6.32-358.18.1-lustre #0 VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform RIP: 0010:[<ffffffff811d1e0c>] [<ffffffff811d1e0c>] nr_blockdev_pages+0x3c/0x80 |
| Comment by James A Simmons [ 16/Jan/14 ] |
|
Now I see the problem with test 133e with the nid stats for the obdfilter layer. I was only looking at 133f test. I have some but not all the debug flags enabled. Which one do you have so I can reproduce this? |
| Comment by Alexey Lyashkov [ 16/Jan/14 ] |
|
I have a few kernel modification to print sentry name have a overflow. i hope it help you. |
| Comment by Alexey Lyashkov [ 17/Jan/14 ] |
|
as i see lprocfs_exp_rd_hash put a data to a fixed buffer size (page size) without a size control, it's produce a overwriting a random area in memory so random memory corruption. |
| Comment by James A Simmons [ 21/Jan/14 ] |
|
Absolute correct. The problem is that __proc_file_read allocates only a single page to use. We have to test if we overflow the page in cfs_hash_debug_str. Once we overflow we have to return which also requires use remembering were we left off. The fix is quite ugly but we can assume the source of the overflow is going to be the looping through the hash bucket. We have to pass in a offset to this function and then if we have a offset jump to the hash bucket loop and start going through the loop at the right place. The other option is to wait for the seq_file patches for server side to land. This would resolve this since seq_file buffers are handled dynamically. That is they are resized on the fly when a overflow happens. |
| Comment by James A Simmons [ 16/May/14 ] |
|
This should be fixed by the landing of http://review.whamcloud.com/#/c/8049 from |
| Comment by Andreas Dilger [ 23/Dec/14 ] |
|
Fixed as part of |