server stops working correctly after Call Trace

warm · 2013-11-19 11:12:52

I use linux-lts on servers. This one is running 3.10.16-1-lts and today it got the next call trace. Before this I've suspected proftpd like a possible reason and have changed it to vsftpd. There were the same server crashes with proftpd. In this case server uptime was 22 days.

What does this mean ? How can I fix this ? Is any workaround ?

Nov 19 06:05:22 my-server kernel: [2812442.750027] INFO: task kworker/0:2:18034 blocked for more than 120 seco
nds.
Nov 19 06:05:22 my-server kernel: [2812442.750132] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
 this message.
Nov 19 06:05:22 my-server kernel: [2812442.750251] kworker/0:2     D ffff88007b6bb028     0 18034      2 0x000
00000
Nov 19 06:05:22 my-server kernel: [2812442.750269] Workqueue: events_long flush_old_commits [reiserfs]
Nov 19 06:05:22 my-server kernel: [2812442.750271]  ffff880009a4bc50 0000000000000046 ffff880009a4bfd8 0000000
000014140
Nov 19 06:05:22 my-server kernel: [2812442.750274]  ffff880009a4bfd8 0000000000014140 ffff88007c0bc280 ffff880
07c7eb380
Nov 19 06:05:22 my-server kernel: [2812442.750277]  0000000000000000 0000000000000fff 0000000000000000 0000000
000000000
Nov 19 06:05:22 my-server kernel: [2812442.750280] Call Trace:
Nov 19 06:05:22 my-server kernel: [2812442.750287]  [<ffffffff814b4a69>] schedule+0x29/0x70
Nov 19 06:05:22 my-server kernel: [2812442.750290]  [<ffffffff814b4dfe>] schedule_preempt_disabled+0xe/0x10
Nov 19 06:05:22 my-server kernel: [2812442.750292]  [<ffffffff814b3524>] __mutex_lock_slowpath+0x144/0x320
Nov 19 06:05:22 my-server kernel: [2812442.750295]  [<ffffffff814b3712>] mutex_lock+0x12/0x30
Nov 19 06:05:22 my-server kernel: [2812442.750301]  [<ffffffffa020204b>] reiserfs_write_lock+0x2b/0x40 [reiser
fs]
Nov 19 06:05:22 my-server kernel: [2812442.750306]  [<ffffffffa01eae9f>] reiserfs_write_dquot+0x1f/0xd0 [reise
rfs]
Nov 19 06:05:22 my-server kernel: [2812442.750310]  [<ffffffff811da334>] dquot_writeback_dquots+0x194/0x1e0
Nov 19 06:05:22 my-server kernel: [2812442.750315]  [<ffffffffa01e9f2b>] reiserfs_sync_fs+0x1b/0x80 [reiserfs]
Nov 19 06:05:22 my-server kernel: [2812442.750318]  [<ffffffff814b33de>] ? mutex_unlock+0xe/0x10
Nov 19 06:05:22 my-server kernel: [2812442.750321]  [<ffffffff81387d97>] ? od_dbs_timer+0xc7/0x160
Nov 19 06:05:22 my-server kernel: [2812442.750326]  [<ffffffffa01e9fd4>] flush_old_commits+0x44/0x50 [reiserfs
]
Nov 19 06:05:22 my-server kernel: [2812442.750330]  [<ffffffff8106fb3b>] process_one_work+0x16b/0x3e0
Nov 19 06:05:22 my-server kernel: [2812442.750332]  [<ffffffff810704d1>] worker_thread+0x121/0x3b0
Nov 19 06:05:22 my-server kernel: [2812442.750335]  [<ffffffff810703b0>] ? manage_workers.isra.23+0x2b0/0x2b0
Nov 19 06:05:22 my-server kernel: [2812442.750338]  [<ffffffff810765a0>] kthread+0xc0/0xd0
Nov 19 06:05:22 my-server kernel: [2812442.750340]  [<ffffffff810764e0>] ? kthread_create_on_node+0x120/0x120
Nov 19 06:05:22 my-server kernel: [2812442.750344]  [<ffffffff814be2ac>] ret_from_fork+0x7c/0xb0
Nov 19 06:05:22 my-server kernel: [2812442.750346]  [<ffffffff810764e0>] ? kthread_create_on_node+0x120/0x120
Nov 19 06:05:22 my-server kernel: [2812442.750349] INFO: task vsftpd:25898 blocked for more than 120 seconds.
Nov 19 06:05:22 my-server kernel: [2812442.750448] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
 this message.
Nov 19 06:05:22 my-server kernel: [2812442.750564] vsftpd          D ffff88007b6bb028     0 25898  25893 0x00000100
Nov 19 06:05:22 my-server kernel: [2812442.750566]  ffff88004bbdd2c0 0000000000000086 ffff88004bbddfd8 0000000000014140
Nov 19 06:05:22 my-server kernel: [2812442.750569]  ffff88004bbddfd8 0000000000014140 ffff8800033a18f0 ffff88004bbddfd8
Nov 19 06:05:22 my-server kernel: [2812442.750572]  ffff88004bbdd3b8 0000000000000000 ffff880000000001 ffff880037e4f4e0
Nov 19 06:05:22 my-server kernel: [2812442.750574] Call Trace:
Nov 19 06:05:22 my-server kernel: [2812442.750580]  [<ffffffffa01f3eaf>] ? search_for_position_by_key.part.14+0xaf/0x290 [reiserfs]
Nov 19 06:05:22 my-server kernel: [2812442.750586]  [<ffffffffa01f53d9>] ? search_for_position_by_key+0x49/0x90 [reiserfs]
Nov 19 06:05:22 my-server kernel: [2812442.750589]  [<ffffffff814b4a69>] schedule+0x29/0x70
Nov 19 06:05:22 my-server kernel: [2812442.750591]  [<ffffffff814b4dfe>] schedule_preempt_disabled+0xe/0x10
Nov 19 06:05:22 my-server kernel: [2812442.750593]  [<ffffffff814b3524>] __mutex_lock_slowpath+0x144/0x320
Nov 19 06:05:22 my-server kernel: [2812442.750596]  [<ffffffff814b3712>] mutex_lock+0x12/0x30
Nov 19 06:05:22 my-server kernel: [2812442.750601]  [<ffffffffa020204b>] reiserfs_write_lock+0x2b/0x40 [reiserfs]
Nov 19 06:05:22 my-server kernel: [2812442.750606]  [<ffffffffa01eb9c5>] reiserfs_quota_write+0x185/0x2b0 [reiserfs]
Nov 19 06:05:22 my-server kernel: [2812442.750608]  [<ffffffff814b33de>] ? mutex_unlock+0xe/0x10
Nov 19 06:05:22 my-server kernel: [2812442.750613]  [<ffffffffa02020a5>] ? reiserfs_write_unlock+0x45/0x50 [reiserfs]
Nov 19 06:05:22 my-server kernel: [2812442.750617]  [<ffffffff811683ae>] ? __kmalloc+0x2e/0x220
Nov 19 06:05:22 my-server kernel: [2812442.750622]  [<ffffffffa0202119>] ? reiserfs_write_unlock_once+0x19/0x20 [reiserfs]
Nov 19 06:05:22 my-server kernel: [2812442.750625]  [<ffffffffa07ed0d4>] ? getdqbuf+0x14/0x40 [quota_tree]
Nov 19 06:05:22 my-server kernel: [2812442.750628]  [<ffffffffa07ed913>] qtree_write_dquot+0xb3/0x150 [quota_tree]
Nov 19 06:05:22 my-server kernel: [2812442.750631]  [<ffffffffa07f205b>] v2_write_dquot+0x2b/0x30 [quota_v2]
Nov 19 06:05:22 my-server kernel: [2812442.750634]  [<ffffffff811d99fb>] dquot_commit+0x8b/0xc0
Nov 19 06:05:22 my-server kernel: [2812442.750638]  [<ffffffffa01eaf04>] reiserfs_write_dquot+0x84/0xd0 [reiserfs]
Nov 19 06:05:22 my-server kernel: [2812442.750643]  [<ffffffffa01eaf82>] reiserfs_mark_dquot_dirty+0x32/0x50 [reiserfs]
Nov 19 06:05:22 my-server kernel: [2812442.750646]  [<ffffffff811dd3b1>] __dquot_alloc_space+0x161/0x210
Nov 19 06:05:22 my-server kernel: [2812442.750649]  [<ffffffff81085ca3>] ? wake_up_process+0x23/0x40
Nov 19 06:05:22 my-server kernel: [2812442.750655]  [<ffffffffa01f707f>] reiserfs_insert_item+0xef/0x350 [reiserfs]
Nov 19 06:05:22 my-server kernel: [2812442.750658]  [<ffffffff8108f46f>] ? load_balance+0xff/0x780
Nov 19 06:05:22 my-server kernel: [2812442.750661]  [<ffffffff81082b2a>] ? update_rq_clock.part.66+0x1a/0x100
Nov 19 06:05:22 my-server kernel: [2812442.750665]  [<ffffffff8106213b>] ? lock_timer_base.isra.35+0x2b/0x50
Nov 19 06:05:22 my-server kernel: [2812442.750667]  [<ffffffff81061d17>] ? internal_add_timer+0x17/0x40
Nov 19 06:05:22 my-server kernel: [2812442.750669]  [<ffffffff810623d1>] ? mod_timer_pending+0xe1/0x180
Nov 19 06:05:22 my-server kernel: [2812442.750672]  [<ffffffff8126018e>] ? cpumask_next_and+0x2e/0x40
Nov 19 06:05:22 my-server kernel: [2812442.750675]  [<ffffffff8126018e>] ? cpumask_next_and+0x2e/0x40
Nov 19 06:05:22 my-server kernel: [2812442.750677]  [<ffffffff8108ea83>] ? find_busiest_group+0x133/0xa20
Nov 19 06:05:22 my-server kernel: [2812442.750683]  [<ffffffffa01f7edd>] indirect2direct+0x1fd/0x280 [reiserfs]
Nov 19 06:05:22 my-server kernel: [2812442.750685]  [<ffffffff814b3302>] ? __mutex_unlock_slowpath+0x82/0x150
Nov 19 06:05:22 my-server kernel: [2812442.750691]  [<ffffffffa01f6389>] reiserfs_cut_from_item+0x319/0x760 [reiserfs]
Nov 19 06:05:22 my-server kernel: [2812442.750693]  [<ffffffff8126018e>] ? cpumask_next_and+0x2e/0x40
Nov 19 06:05:22 my-server kernel: [2812442.750695]  [<ffffffff8126018e>] ? cpumask_next_and+0x2e/0x40
Nov 19 06:05:22 my-server kernel: [2812442.750702]  [<ffffffffa01f69f3>] reiserfs_do_truncate+0x223/0x520 [reiserfs]
Nov 19 06:05:22 my-server kernel: [2812442.750704]  [<ffffffff814b3302>] ? __mutex_unlock_slowpath+0x82/0x150
Nov 19 06:05:22 my-server kernel: [2812442.750710]  [<ffffffffa01e0fbf>] reiserfs_truncate_file+0x1ef/0x3a0 [reiserfs]
Nov 19 06:05:22 my-server kernel: [2812442.750715]  [<ffffffffa01e5632>] reiserfs_file_release+0x292/0x350 [reiserfs]
Nov 19 06:05:22 my-server kernel: [2812442.750718]  [<ffffffff81181f14>] __fput+0xa4/0x230
Nov 19 06:05:22 my-server kernel: [2812442.750720]  [<ffffffff8118215e>] ____fput+0xe/0x10
Nov 19 06:05:22 my-server kernel: [2812442.750723]  [<ffffffff8107343f>] task_work_run+0x9f/0xe0
Nov 19 06:05:22 my-server kernel: [2812442.750726]  [<ffffffff81011d8c>] do_notify_resume+0x8c/0xa0
Nov 19 06:05:22 my-server kernel: [2812442.750729]  [<ffffffff814be61a>] int_signal+0x12/0x17
Nov 19 06:05:22 my-server kernel: [2812442.750731] INFO: task vsftpd:25904 blocked for more than 120 seconds.
Nov 19 06:05:22 my-server kernel: [2812442.750830] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 19 06:05:22 my-server kernel: [2812442.750946] vsftpd          D ffff88007b6bc950     0 25904  25899 0x00000100
Nov 19 06:05:22 my-server kernel: [2812442.750949]  ffff880062c6b680 0000000000000082 ffff880062c6bfd8 0000000000014140
Nov 19 06:05:22 my-server kernel: [2812442.750951]  ffff880062c6bfd8 0000000000014140 ffff8800033a2140 ffffffff811afd1f
Nov 19 06:05:22 my-server kernel: [2812442.750954]  ffff8800081cc388 ffff880062c6b910 ffff880062c6bdd8 0000000000000000
Nov 19 06:05:22 my-server kernel: [2812442.750957] Call Trace:
Nov 19 06:05:22 my-server kernel: [2812442.750960]  [<ffffffff811afd1f>] ? __find_get_block+0xbf/0x230
Nov 19 06:05:22 my-server kernel: [2812442.750966]  [<ffffffffa01f7242>] ? reiserfs_insert_item+0x2b2/0x350 [reiserfs]
Nov 19 06:05:22 my-server kernel: [2812442.750968]  [<ffffffff810772f5>] ? wake_up_bit+0x25/0x30
Nov 19 06:05:22 my-server kernel: [2812442.750971]  [<ffffffff811ae6f7>] ? unlock_buffer+0x17/0x20
Nov 19 06:05:22 my-server kernel: [2812442.750973]  [<ffffffff814b4a69>] schedule+0x29/0x70
Nov 19 06:05:22 my-server kernel: [2812442.750976]  [<ffffffff814b4dfe>] schedule_preempt_disabled+0xe/0x10
Nov 19 06:05:22 my-server kernel: [2812442.750978]  [<ffffffff814b3524>] __mutex_lock_slowpath+0x144/0x320
Nov 19 06:05:22 my-server kernel: [2812442.750980]  [<ffffffff814b3712>] mutex_lock+0x12/0x30
Nov 19 06:05:22 my-server kernel: [2812442.750983]  [<ffffffff811d9999>] dquot_commit+0x29/0xc0
Nov 19 06:05:22 my-server kernel: [2812442.750988]  [<ffffffffa01eaf04>] reiserfs_write_dquot+0x84/0xd0 [reiserfs]
Nov 19 06:05:22 my-server kernel: [2812442.750993]  [<ffffffffa01eaf82>] reiserfs_mark_dquot_dirty+0x32/0x50 [reiserfs]
Nov 19 06:05:22 my-server kernel: [2812442.750996]  [<ffffffff811dd579>] __dquot_free_space+0x119/0x2b0
Nov 19 06:05:22 my-server kernel: [2812442.750998]  [<ffffffff810772f5>] ? wake_up_bit+0x25/0x30
Nov 19 06:05:22 my-server kernel: [2812442.751003]  [<ffffffffa01d944c>] _reiserfs_free_block+0x18c/0x1d0 [reiserfs]
Nov 19 06:05:22 my-server kernel: [2812442.751008]  [<ffffffffa01d9502>] reiserfs_free_block+0x72/0xb0 [reiserfs]
Nov 19 06:05:22 my-server kernel: [2812442.751013]  [<ffffffffa01f5813>] prepare_for_delete_or_cut+0x3a3/0x570 [reiserfs]
Nov 19 06:05:22 my-server kernel: [2812442.751018]  [<ffffffffa01f612a>] reiserfs_cut_from_item+0xba/0x760 [reiserfs]
Nov 19 06:05:22 my-server kernel: [2812442.751021]  [<ffffffff81089388>] ? __enqueue_entity+0x78/0x80
Nov 19 06:05:22 my-server kernel: [2812442.751027]  [<ffffffffa01f69f3>] reiserfs_do_truncate+0x223/0x520 [reiserfs]
Nov 19 06:05:22 my-server kernel: [2812442.751030]  [<ffffffff814b3301>] ? __mutex_unlock_slowpath+0x81/0x150
Nov 19 06:05:22 my-server kernel: [2812442.751035]  [<ffffffffa01e0fbf>] reiserfs_truncate_file+0x1ef/0x3a0 [reiserfs]
Nov 19 06:05:22 my-server kernel: [2812442.751040]  [<ffffffffa01e5632>] reiserfs_file_release+0x292/0x350 [reiserfs]
Nov 19 06:05:22 my-server kernel: [2812442.751042]  [<ffffffff81181f14>] __fput+0xa4/0x230
Nov 19 06:05:22 my-server kernel: [2812442.751045]  [<ffffffff8118215e>] ____fput+0xe/0x10
Nov 19 06:05:22 my-server kernel: [2812442.751047]  [<ffffffff8107343f>] task_work_run+0x9f/0xe0
Nov 19 06:05:22 my-server kernel: [2812442.751049]  [<ffffffff81011d8c>] do_notify_resume+0x8c/0xa0
Nov 19 06:05:22 my-server kernel: [2812442.751052]  [<ffffffff814be61a>] int_signal+0x12/0x17
Nov 19 06:05:22 my-server kernel: [2812442.751055] INFO: task kworker/u8:0:30662 blocked for more than 120 seconds.
Nov 19 06:05:22 my-server kernel: [2812442.751158] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 19 06:05:22 my-server kernel: [2812442.751273] kworker/u8:0    D ffff880010395a10     0 30662      2 0x00000000
Nov 19 06:05:22 my-server kernel: [2812442.751278] Workqueue: writeback bdi_writeback_workfn (flush-9:1)
Nov 19 06:05:22 my-server kernel: [2812442.751280]  ffff880010395980 0000000000000046 ffff880010395fd8 0000000000014140
Nov 19 06:05:22 my-server kernel: [2812442.751282]  ffff880010395fd8 0000000000014140 ffff880011b78850 ffffffffa0096f80
Nov 19 06:05:22 my-server kernel: [2812442.751285]  ffff880046e79100 0000000000000020 ffff880046e79158 ffff88007b1c0000
Nov 19 06:05:22 my-server kernel: [2812442.751288] Call Trace:
Nov 19 06:05:22 my-server kernel: [2812442.751293]  [<ffffffff81244eab>] ? blk_rq_map_sg+0x8b/0x1f0
Nov 19 06:05:22 my-server kernel: [2812442.751296]  [<ffffffff8111ab50>] ? filemap_fdatawait+0x30/0x30
Nov 19 06:05:22 my-server kernel: [2812442.751299]  [<ffffffff814b4a69>] schedule+0x29/0x70
Nov 19 06:05:22 my-server kernel: [2812442.751301]  [<ffffffff814b4cef>] io_schedule+0x8f/0xe0
Nov 19 06:05:22 my-server kernel: [2812442.751303]  [<ffffffff8111ab5e>] sleep_on_page+0xe/0x20
Nov 19 06:05:22 my-server kernel: [2812442.751306]  [<ffffffff814b28eb>] __wait_on_bit_lock+0x5b/0xc0
Nov 19 06:05:22 my-server kernel: [2812442.751308]  [<ffffffff8111ac9a>] __lock_page+0x6a/0x70
Nov 19 06:05:22 my-server kernel: [2812442.751310]  [<ffffffff81077340>] ? autoremove_wake_function+0x40/0x40
Nov 19 06:05:22 my-server kernel: [2812442.751313]  [<ffffffff81127361>] ? pagevec_lookup_tag+0x21/0x30
Nov 19 06:05:22 my-server kernel: [2812442.751316]  [<ffffffff81124f73>] write_cache_pages+0x403/0x4b0
Nov 19 06:05:22 my-server kernel: [2812442.751319]  [<ffffffff81124890>] ? mapping_tagged+0x20/0x20
Nov 19 06:05:22 my-server kernel: [2812442.751321]  [<ffffffff81125060>] generic_writepages+0x40/0x60
Nov 19 06:05:22 my-server kernel: [2812442.751324]  [<ffffffff811266c5>] do_writepages+0x35/0x40
Nov 19 06:05:22 my-server kernel: [2812442.751327]  [<ffffffff811a7be0>] __writeback_single_inode+0x40/0x210
Nov 19 06:05:22 my-server kernel: [2812442.751329]  [<ffffffff811a8915>] writeback_sb_inodes+0x195/0x400
Nov 19 06:05:22 my-server kernel: [2812442.751332]  [<ffffffff811a8c1f>] __writeback_inodes_wb+0x9f/0xd0
Nov 19 06:05:22 my-server kernel: [2812442.751334]  [<ffffffff811a8e83>] wb_writeback+0x233/0x2b0
Nov 19 06:05:22 my-server kernel: [2812442.751337]  [<ffffffff811a9665>] wb_do_writeback+0x1e5/0x1f0
Nov 19 06:05:22 my-server kernel: [2812442.751340]  [<ffffffff811a96ea>] bdi_writeback_workfn+0x7a/0x1d0
Nov 19 06:05:22 my-server kernel: [2812442.751342]  [<ffffffff8106fb3b>] process_one_work+0x16b/0x3e0
Nov 19 06:05:22 my-server kernel: [2812442.751345]  [<ffffffff810704d1>] worker_thread+0x121/0x3b0
Nov 19 06:05:22 my-server kernel: [2812442.751347]  [<ffffffff810703b0>] ? manage_workers.isra.23+0x2b0/0x2b0
Nov 19 06:05:22 my-server kernel: [2812442.751350]  [<ffffffff810765a0>] kthread+0xc0/0xd0
Nov 19 06:05:22 my-server kernel: [2812442.751352]  [<ffffffff810764e0>] ? kthread_create_on_node+0x120/0x120
Nov 19 06:05:22 my-server kernel: [2812442.751355]  [<ffffffff814be2ac>] ret_from_fork+0x7c/0xb0
Nov 19 06:05:22 my-server kernel: [2812442.751357]  [<ffffffff810764e0>] ? kthread_create_on_node+0x120/0x120

After this load average slowly gets to 300 , some services die and server does not reboots on reboot command and even sysrq does not helped today (echo "s" | tee /proc/sysrq-trigger ; echo "u" | tee /proc/sysrq-trigger ; echo "b" | tee /proc/sysrq-trigger).

Help me pleace :-).

Lone_Wolf · 2013-11-19 11:31:59

i'm a newbie when it comes to call traces, but i do see a lot of reiserfs related messages.

I'd check for harddrive problems, and if you use diskquota verify they are not the cause.

warm · 2013-11-19 14:08:49

Lone_Wolf wrote:

i'm a newbie when it comes to call traces, but i do see a lot of reiserfs related messages.
I'd check for harddrive problems, and if you use diskquota verify they are not the cause.

I have checked "smartctl -a" output and it show zerro Reallocated_Sector_Ct counters on both drives (I use soft raid-1 and I cannot run longtime disk checks). Also I have umounted /dev/md1 (this is separate partition for ftp service and assuming that trace contains strings about vsftpd) and checked it with reiserfsck -- no errors. Then I've mounted it back and checket quotas -- all seems fine. I cannot turn off quotas.

Seems that I get underground knocking problem :-) or electromagnetic compatibility problem ...

BeepDog · 2013-12-18 20:47:49

I have this problem on a 3.12.5-1-ARCH Xen vm, but only on that one VM. The disks are backed by a mdadm raid10 array. So I doubt it's the disks, since I'm only seeing this problem on this one VM.

My other VMs, also with reiserfs Systems, and some with far higher IO load than this one, are on 3.11.

Something is very odd.

I found this: https://bugzilla.kernel.org/show_bug.cgi?id=29162#c51 but that claims it's been fixed in 3.12-rc1, so I would assume that whatever was added should work just fine. I don't fully understand what's going on here.

Arch Linux

#1 2013-11-19 11:12:52

server stops working correctly after Call Trace

#2 2013-11-19 11:31:59

Re: server stops working correctly after Call Trace

#3 2013-11-19 14:08:49

Re: server stops working correctly after Call Trace

#4 2013-12-18 20:47:49

Re: server stops working correctly after Call Trace

Board footer