[LU-4528] osd_trans_exec_op()) ASSERTION( oti->oti_declare_ops_rb[rb] > 0 ) failed: rb = 0

• Type: Bug
• Resolution: Fixed
• Priority: Blocker
• Fix Version/s: Lustre 2.6.0
• Affects Version/s: Lustre 2.6.0, Lustre 2.4.2, Lustre 2.5.1
• Severity: 3
• Assignee: Mikhail Pershin
• Reporter: Sarah Liu

Description

When running sanity on the latest master build, hit following LBUG on client:

Lustre: DEBUG MARKER: == sanity test 60a: llog sanity tests run from kernel module ============ 15:06:20 (1390431980)
Lustre: DEBUG MARKER: test_60 run 3219 - from kernel mode
Lustre: 9324:0:(llog_test.c:1018:llog_test_setup()) Setup llog-test device over MGS device
Lustre: 9324:0:(llog_test.c:110:llog_test_1()) 1a: create a log with name: aee6dfbf
Lustre: 9324:0:(llog_test.c:127:llog_test_1()) 1b: close newly-created log
Lustre: 9324:0:(llog_test.c:151:llog_test_2()) 2a: re-open a log with name: aee6dfbf
Lustre: 9324:0:(llog_test.c:232:llog_test_3()) 3a: write one create_rec
Lustre: 9324:0:(llog_test.c:244:llog_test_3()) 3b: write 10 cfg log records with 8 bytes bufs
Lustre: 9324:0:(llog_test.c:265:llog_test_3()) 3c: write 1000 more log records
Lustre: 9324:0:(llog_test.c:280:llog_test_3()) 3d: write log more than BITMAP_SIZE, return -ENOSPC
Lustre: 9324:0:(llog_test.c:311:llog_test_3()) 3d: wrote 64364 more records before end of llog is reached
Lustre: 9324:0:(llog_test.c:340:llog_test_4()) 4a: create a catalog log with name: aee6dfc0
Lustre: 9324:0:(llog_test.c:355:llog_test_4()) 4b: write 1 record into the catalog
Lustre: 9324:0:(llog_test.c:370:llog_test_4()) 4c: cancel 1 log record
Lustre: 9324:0:(llog_test.c:382:llog_test_4()) 4d: write 65536 more log records
Lustre: 9324:0:(llog_test.c:398:llog_test_4()) 4e: add 5 large records, one record per block
Lustre: 9324:0:(llog_test.c:418:llog_test_4()) 4f: put newly-created catalog
Lustre: 9324:0:(llog_test.c:516:llog_test_5()) 5a: re-open catalog by id
Lustre: 9324:0:(llog_test.c:529:llog_test_5()) 5b: print the catalog entries.. we expect 2
Lustre: 9325:0:(llog_test.c:447:cat_print_cb()) seeing record at index 1 - [0x1:0xc:0x0] in log [0xa:0xb:0x0]
Lustre: 9325:0:(llog_test.c:447:cat_print_cb()) seeing record at index 2 - [0x1:0xd:0x0] in log [0xa:0xb:0x0]
Lustre: 9324:0:(llog_test.c:541:llog_test_5()) 5c: Cancel 65536 records, see one log zapped
Lustre: 9324:0:(llog_test.c:549:llog_test_5()) 5c: print the catalog entries.. we expect 1
Lustre: 9324:0:(llog_test.c:561:llog_test_5()) 5d: add 1 record to the log with many canceled empty pages
Lustre: 9324:0:(llog_test.c:569:llog_test_5()) 5e: print plain log entries.. expect 6
Lustre: 9324:0:(llog_test.c:581:llog_test_5()) 5f: print plain log entries reversely.. expect 6
Lustre: 9324:0:(llog_test.c:595:llog_test_5()) 5g: close re-opened catalog
Lustre: 9324:0:(llog_test.c:625:llog_test_6()) 6a: re-open log aee6dfbf using client API
Lustre: MGS: non-config logname received: aee6dfbf
Lustre: 9324:0:(llog_test.c:657:llog_test_6()) 6b: process log aee6dfbf using client API
Lustre: 9324:0:(llog_test.c:661:llog_test_6()) 6b: processed 64364 records
Lustre: 9324:0:(llog_test.c:668:llog_test_6()) 6c: process log aee6dfbf reversely using client API
Lustre: 9324:0:(llog_test.c:672:llog_test_6()) 6c: processed 64364 records
Lustre: 9324:0:(llog_test.c:820:llog_test_7()) 7a: test llog_logid_rec
LustreError: 9324:0:(osd_io.c:1396:osd_ldiskfs_write_record()) loop0: error reading offset 1794048 (block 438): rc = -28
LustreError: 9324:0:(llog_osd.c:156:llog_osd_write_blob()) lustre-MDT0000-osd: error writing log record: rc = -28
LustreError: 9324:0:(osd_internal.h:970:osd_trans_exec_op()) ASSERTION( oti->oti_declare_ops_rb[rb] > 0 ) failed: rb = 0
LustreError: 9324:0:(osd_internal.h:970:osd_trans_exec_op()) LBUG
Pid: 9324, comm: lctl

Message from
Call Trace:
 [<ffffffffa0369895>] libcfs_debug_dumpstack+0x55/0x80 [libcfs]
 [<ffffffffa0369e97>] lbug_with_loc+0x47/0xb0 [libcfs]
 [<ffffffffa0ccdb3b>] osd_trans_exec_op+0x2ab/0x2e0 [osd_ldiskfs]
 [<ffffffffa0ce0583>] osd_attr_set+0xe3/0x540 [osd_ldiskfs]
 [<ffffffffa0ced713>] ? osd_punch+0x1d3/0x620 [osd_ldiskfs]
 [<ffffffffa04b5081>] llog_osd_write_blob+0x211/0x850 [obdclass]
 [<ffffffffa04b906d>] llog_osd_write_rec+0xacd/0x1390 [obdclass]
 syslogd@client- [<ffffffffa04a74f8>] llog_write_rec+0xc8/0x290 [obdclass]
 [<ffffffffa04a8c6d>] llog_write+0x2ad/0x420 [obdclass]
 [<ffffffffa04594fd>] llog_test_7_sub+0x16d/0xaf0 [llog_test]
3 at Jan 22 15:0 [<ffffffffa0459fbf>] llog_test_7+0x13f/0xa10 [llog_test]
 [<ffffffffa045bd4a>] llog_run_tests+0x14ba/0x1e50 [llog_test]
 [<ffffffffa04b179e>] ? llog_setup+0x3be/0x910 [obdclass]
 [<ffffffffa045ce59>] llog_test_setup+0x779/0x8c0 [llog_test]
 [<ffffffffa04e2ebb>] obd_setup+0x19b/0x290 [obdclass]
 [<ffffffff81168043>] ? kmem_cache_alloc_trace+0x1a3/0x1b0
6:22 ...
 kern [<ffffffffa04c601b>] ? class_new_export+0x72b/0x960 [obdclass]
 [<ffffffffa04e31b8>] class_setup+0x208/0x870 [obdclass]
 [<ffffffffa04eb72c>] class_process_config+0xc6c/0x1ad0 [obdclass]
 [<ffffffff811685ac>] ? __kmalloc+0x20c/0x220
 [<ffffffffa04a4d6d>] ? obd_ioctl_getdata+0x12d/0x1120 [obdclass]
 [<ffffffffa04bd3fb>] class_handle_ioctl+0x3bb/0x1ef0 [obdclass]
 [<ffffffffa04a42ab>] obd_class_ioctl+0x4b/0x190 [obdclass]
 [<ffffffff81195382>] vfs_ioctl+0x22/0xa0
 [<ffffffff81195524>] do_vfs_ioctl+0x84/0x580
 [<ffffffff81182bf1>] ? __fput+0x1a1/0x210
 [<ffffffff81195aa1>] sys_ioctl+0x81/0xa0
 [<ffffffff8100b072>] system_call_fastpath+0x16/0x1b

Issue Links

• is duplicated by: LU-4899 osd_trans_exec_op()) ASSERTION( oti->oti_declare_ops_rb[rb] > 0 ) failed: rb = 0
• is related to: LU-6556 changelog catalog corruption if all possible records is define
• is related to: LU-5303 osd_trans_exec_op()) ASSERTION( oti->oti_declare_ops_rb[rb] > 0 ) failed: rb = 0
• is related to: LU-4183 MDS crash when running fsx with NFS export
• is related to: LU-5794 improve credit checks in osd-ldiskfs
• is related to: LU-4901 Remove triple buffer update from llog_osd_write_blob()