Hi Damiri,<br><br>From the logs you have provided it looks like you have a problem with your back end storage. First of all we can see that your SRP connection to backend storage reports abort and reset (I guess your backend storage hardware is connected via Infiniband if you are using SRP). Then Lustre reports slow messages and eventually kernel reports SCSI errors. Device mapper reports that both paths to the device are failed and Lustre remounts filesystem read-only due to I/O error. All these means that your I/O node lost contact with the OST due to some errors either on IB network connecting your host to the storage hardware or on the storage hardware itself. From the first part of the log we can see that the device being in trouble is OST es1-OST000b (dm-11). In the second part of your log I can not see that device being mounted. From your log I can see that only OST  es1-OST000a (dm-10) is mounted and enters recovery (id that a complete lustre start up log?). You need to check if your I/O node can actually still see and access OST es1-OST000b (dm-11), if yes then run fsck on that device and then try to mount it. If your host can not see that device you will have to investigate the IB network, storage devices and also it is worth checking multipath configuration (incorrect multipath config may not create all necessary devices).<br>
<br>Good luck!<br><br>Wojciech<br><br><br><br><div class="gmail_quote">On 18 July 2011 16:28, Young, Damiri <span dir="ltr"><<a href="mailto:Damiri.Young@unt.edu">Damiri.Young@unt.edu</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex;">





<div>
<div style="direction:ltr;font-family:Tahoma;color:#000000;font-size:10pt">Hi All,<br>
On Friday 1 of the 4 I/O nodes in our lustre network began logging the following slow start_page_write errors for some OSTs:<br>
--------------------------------------------------- messages -----------------------------------------------------------------------------------<br>
Jul 15 12:55:32 IO-10 heartbeat: [21053]: info: Checking status of STONITH device [IPMI STONITH device ]<br>
Jul 15 12:55:32 IO-10 heartbeat: [16746]: info: Managed STONITH-stat process 21053 exited with return code 0.<br>
Jul 15 13:02:25 IO-10 kernel: Lustre: 18616:0:(filter_io.c:652:filter_preprw_write()) es1-OST000b: slow start_page_write 44s<br>
Jul 15 13:02:25 IO-10 kernel: Lustre: 18688:0:(filter_io_26.c:779:filter_commitrw_write()) es1-OST000b: slow direct_io 44s<br>
Jul 15 13:02:57 IO-10 kernel: Lustre: 18531:0:(filter_io.c:652:filter_preprw_write()) es1-OST000b: slow start_page_write 38s<br>
Jul 15 13:03:29 IO-10 kernel: Lustre: 18566:0:(filter_io_26.c:779:filter_commitrw_write()) es1-OST000b: slow direct_io 32s<br>
Jul 15 13:03:29 IO-10 kernel:  host2: SRP abort called<br>
Jul 15 13:03:29 IO-10 last message repeated 4 times<br>
Jul 15 13:03:29 IO-10 kernel:  host2: SRP reset_device called<br>
Jul 15 13:03:29 IO-10 kernel:  host2: ib_srp: SRP reset_host called state 0 qp_err 0<br>
Jul 15 13:03:39 IO-10 kernel: sd 2:0:0:12: SCSI error: return code = 0x06000000<br>
Jul 15 13:03:39 IO-10 kernel: end_request: I/O error, dev sdag, sector 15012385240<br>
Jul 15 13:03:39 IO-10 kernel: device-mapper: multipath: Failing path 66:0.<br>
Jul 15 13:03:39 IO-10 kernel: sd 2:0:0:12: SCSI error: return code = 0x06000000<br>
Jul 15 13:03:39 IO-10 kernel: end_request: I/O error, dev sdag, sector 15012386176<br>
Jul 15 13:03:39 IO-10 kernel: sd 2:0:0:12: SCSI error: return code = 0x06000000<br>
Jul 15 13:03:39 IO-10 kernel: end_request: I/O error, dev sdag, sector 15012386696<br>
Jul 15 13:03:39 IO-10 kernel: sd 2:0:0:12: SCSI error: return code = 0x06000000<br>
Jul 15 13:03:39 IO-10 kernel: end_request: I/O error, dev sdag, sector 15012385256<br>
Jul 15 13:03:39 IO-10 kernel: sd 2:0:0:12: SCSI error: return code = 0x06000000<br>
Jul 15 13:03:39 IO-10 kernel: end_request: I/O error, dev sdag, sector 15012385568<br>
Jul 15 13:03:39 IO-10 multipathd: 66:0: mark as failed <br>
Jul 15 13:03:39 IO-10 multipathd: lun_12: remaining active paths: 1 <br>
Jul 15 13:04:35 IO-10 kernel: LustreError: 18538:0:(filter_io_26.c:779:filter_commitrw_write()) es1-OST000b: slow direct_io 50s<br>
Jul 15 13:04:35 IO-10 kernel: Lustre: 18447:0:(filter_io_26.c:779:filter_commitrw_write()) es1-OST000b: slow direct_io 31s<br>
Jul 15 13:04:35 IO-10 kernel: Lustre: 18525:0:(filter_io.c:652:filter_preprw_write()) es1-OST000b: slow start_page_write 46s<br>
Jul 15 13:04:35 IO-10 kernel: LustreError: 18598:0:(lustre_fsfilt.h:318:fsfilt_commit_wait()) es1-OST000b: slow journal start 56s<br>
Jul 15 13:04:35 IO-10 kernel: LustreError: 18393:0:(filter_io_26.c:792:filter_commitrw_write()) es1-OST000b: slow commitrw commit 56s<br>
Jul 15 13:04:35 IO-10 kernel: LustreError: 18393:0:(filter_io_26.c:792:filter_commitrw_write()) Skipped 1 previous similar message<br>
Jul 15 13:04:35 IO-10 kernel: Lustre: 18739:0:(lustre_fsfilt.h:318:fsfilt_commit_wait()) es1-OST000b: slow journal start 46s<br>
Jul 15 13:04:35 IO-10 kernel: Lustre: 18739:0:(filter_io_26.c:792:filter_commitrw_write()) es1-OST000b: slow commitrw commit 46s<br>
Jul 15 13:04:35 IO-10 kernel: Lustre: 18422:0:(lustre_fsfilt.h:318:fsfilt_commit_wait()) es1-OST000b: slow journal start 31s<br>
Jul 15 13:04:35 IO-10 kernel: Lustre: 18422:0:(lustre_fsfilt.h:318:fsfilt_commit_wait()) Skipped 5 previous similar messages<br>
Jul 15 13:04:35 IO-10 kernel: Lustre: 18422:0:(filter_io_26.c:792:filter_commitrw_write()) es1-OST000b: slow commitrw commit 31s<br>
Jul 15 13:04:35 IO-10 kernel: Lustre: 18422:0:(filter_io_26.c:792:filter_commitrw_write()) Skipped 5 previous similar messages<br>
Jul 15 13:04:35 IO-10 kernel: LustreError: 18644:0:(lustre_fsfilt.h:318:fsfilt_commit_wait()) es1-OST000b: slow journal start 56s<br>
Jul 15 13:04:35 IO-10 kernel: LustreError: 18644:0:(lustre_fsfilt.h:318:fsfilt_commit_wait()) Skipped 5 previous similar messages<br>
Jul 15 13:04:35 IO-10 kernel: LustreError: 18644:0:(filter_io_26.c:792:filter_commitrw_write()) es1-OST000b: slow commitrw commit 56s<br>
Jul 15 13:04:35 IO-10 kernel: LustreError: 18644:0:(filter_io_26.c:792:filter_commitrw_write()) Skipped 4 previous similar messages<br>
Jul 15 13:04:35 IO-10 kernel: LustreError: 18598:0:(lustre_fsfilt.h:318:fsfilt_commit_wait()) Skipped 4 previous similar messages<br>
Jul 15 13:04:35 IO-10 kernel: LustreError: 18766:0:(filter_io_26.c:779:filter_commitrw_write()) es1-OST000b: slow direct_io 55s<br>
Jul 15 13:04:35 IO-10 kernel: LustreError: 18766:0:(filter_io_26.c:779:filter_commitrw_write()) Skipped 1 previous similar message<br>
Jul 15 13:05:07 IO-10 kernel: Lustre: 18650:0:(filter_io_26.c:779:filter_commitrw_write()) es1-OST000b: slow direct_io 31s<br>
Jul 15 13:05:07 IO-10 kernel: Lustre: 18650:0:(filter_io_26.c:779:filter_commitrw_write()) Skipped 2 previous similar messages<br>
Jul 15 13:05:08 IO-10 kernel:  host1: SRP abort called<br>
Jul 15 13:05:08 IO-10 kernel:  host1: SRP reset_device called<br>
Jul 15 13:05:08 IO-10 kernel:  host1: ib_srp: SRP reset_host called state 0 qp_err 0<br>
Jul 15 13:05:18 IO-10 kernel: sd 1:0:0:12: SCSI error: return code = 0x00000002<br>
Jul 15 13:05:18 IO-10 kernel: end_request: I/O error, dev sdm, sector 861112<br>
Jul 15 13:05:18 IO-10 kernel: device-mapper: multipath: Failing path 8:192.<br>
Jul 15 13:05:18 IO-10 kernel: Buffer I/O error on device dm-11, logical block 107639<br>
Jul 15 13:05:18 IO-10 kernel: lost page write due to I/O error on dm-11<br>
Jul 15 13:05:18 IO-10 kernel: LDISKFS-fs error (device dm-11): kmmpd: Error writing to MMP block<br>
Jul 15 13:05:18 IO-10 kernel: Remounting filesystem read-only<br>
Jul 15 13:05:18 IO-10 kernel: LustreError: 18499:0:(fsfilt-ldiskfs.c:438:fsfilt_ldiskfs_brw_start()) can't get handle for 99 credits: rc = -3<br>
0<br>
Jul 15 13:05:18 IO-10 kernel: Lustre: 18657:0:(filter_io_26.c:779:filter_commitrw_write()) es1-OST000b: slow direct_io 36s<br>
Jul 15 13:05:18 IO-10 multipathd: 8:192: mark as failed <br>
Jul 15 13:05:18 IO-10 kernel: Lustre: 18657:0:(filter_io_26.c:779:filter_commitrw_write()) Skipped 1 previous similar message<br>
Jul 15 13:05:18 IO-10 kernel: Buffer I/O error on device dm-11, logical block 79917<br>
Jul 15 13:05:18 IO-10 multipathd: lun_12: remaining active paths: 0 <br>
Jul 15 13:05:18 IO-10 kernel: lost page write due to I/O error on dm-11<br>
Jul 15 13:05:18 IO-10 kernel: Aborting journal on device dm-11.<br>
Jul 15 13:05:18 IO-10 kernel: LustreError: 19103:0:(obd.h:1188:obd_transno_commit_cb()) es1-OST000b: transno 608801934 commit error: 2<br>
<br>
------------------------------------------- end messages -------------------------------------------------------------------------<br>
<br>
<br>
I then tried to fsck -n one of the mentioned devices for inconsistencies at which point I noticed on a kernel  panic. Rebooted the machine which appears to not be able to establish a connection or LNET:<br>
-----------------------------------------------------messages ---------------------------------------------------------------------<br>
<div>Jul 18 09:24:44 IO-10 OpenSM[28708]: /var/log/opensm.log log file opened <br>
Jul 18 09:24:44 IO-10 OpenSM[28708]: OpenSM 3.1.11 <br>
Jul 18 09:24:44 IO-10 OpenSM[28708]: Entering STANDBY state  <br>
Jul 18 09:28:23 IO-10 run_srp_daemon[28757]: failed srp_daemon: [HCA=mlx4_0] [port=2] [exit status=110]. Will try to restart srp_daemon perio<br>
dically. No more warnings will be issued in the next 7200 seconds if the same problem repeats<br>
Jul 18 09:28:23 IO-10 run_srp_daemon[28763]: failed srp_daemon: [HCA=mlx4_0] [port=1] [exit status=110]. Will try to restart srp_daemon perio<br>
dically. No more warnings will be issued in the next 7200 seconds if the same problem repeats<br>
Jul 18 09:28:24 IO-10 run_srp_daemon[28769]: starting srp_daemon: [HCA=mlx4_0] [port=2]<br>
Jul 18 09:28:25 IO-10 run_srp_daemon[28782]: starting srp_daemon: [HCA=mlx4_0] [port=1]<br>
Jul 18 09:33:10 IO-10 kernel: megasas: 00.00.03.15-RH1 Wed Nov. 21 10:29:45 PST 2007<br>
Jul 18 09:33:10 IO-10 kernel: Lustre: OBD class driver, <a href="http://www.lustre.org/" target="_blank">http://www.lustre.org/</a><br>
Jul 18 09:33:10 IO-10 kernel:         Lustre Version: 1.6.6<br>
Jul 18 09:33:10 IO-10 kernel:         Build Version: 1.6.6-1.6.6-ddn3.1-20090527173746<br>
Jul 18 09:33:10 IO-10 kernel: Lustre: 30493:0:(o2iblnd_modparams.c:324:kiblnd_tunables_init()) Concurrent sends 7 is lower than message queue<br>
 size: 8, performance may drop slightly.<br>
Jul 18 09:33:10 IO-10 kernel: Lustre: Added LNI 10.1.0.229@o2ib [8/64]<br>
Jul 18 09:33:11 IO-10 kernel: Lustre: Lustre Client File System; <a href="http://www.lustre.org/" target="_blank">http://www.lustre.org/</a><br>
Jul 18 09:33:34 IO-10 kernel: kjournald starting.  Commit interval 5 seconds<br>
Jul 18 09:33:34 IO-10 kernel: LDISKFS-fs warning: checktime reached, running e2fsck is recommended<br>
Jul 18 09:33:34 IO-10 kernel: LDISKFS FS on dm-10, internal journal<br>
Jul 18 09:33:34 IO-10 kernel: LDISKFS-fs: recovery complete.<br>
Jul 18 09:33:34 IO-10 kernel: LDISKFS-fs: mounted filesystem with ordered data mode.<br>
Jul 18 09:33:34 IO-10 multipathd: dm-10: umount map (uevent) <br>
Jul 18 09:33:45 IO-10 kernel: kjournald starting.  Commit interval 5 seconds<br>
Jul 18 09:33:45 IO-10 kernel: LDISKFS-fs warning: checktime reached, running e2fsck is recommended<br>
Jul 18 09:33:45 IO-10 kernel: LDISKFS FS on dm-10, internal journal<br>
Jul 18 09:33:45 IO-10 kernel: LDISKFS-fs: mounted filesystem with ordered data mode.<br>
Jul 18 09:33:45 IO-10 kernel: LDISKFS-fs: file extents enabled<br>
Jul 18 09:33:45 IO-10 kernel: LDISKFS-fs: mballoc enabled<br>
Jul 18 09:33:45 IO-10 kernel: LustreError: 137-5: UUID 'es1-OST000a_UUID' is not available  for connect (no target)<br>
Jul 18 09:33:45 IO-10 kernel: LustreError: 30789:0:(ldlm_lib.c:1619:target_send_reply_msg()) @@@ processing error (-19)  req@ffff8101a6992c00<br>
 x5558026/t0 o8-><?>@<?>:0/0 lens 304/0 e 0 to 0 dl 1310999725 ref 1 fl Interpret:/0/0 rc -19/0<br>
Jul 18 09:33:45 IO-10 kernel: LustreError: 30789:0:(ldlm_lib.c:1619:target_send_reply_msg()) Skipped 2 previous similar messages<br>
Jul 18 09:33:45 IO-10 kernel: fsfilt_ldiskfs: no version for "ldiskfs_free_blocks" found: kernel tainted.<br>
Jul 18 09:33:45 IO-10 kernel: Lustre: Filtering OBD driver; <a href="http://www.lustre.org/" target="_blank">http://www.lustre.org/</a><br>
Jul 18 09:33:45 IO-10 kernel: Lustre: 31834:0:(filter.c:868:filter_init_server_data()) RECOVERY: service es1-OST000a, 249 recoverable clients<br>
, last_rcvd 469616249<br>
Jul 18 09:33:45 IO-10 kernel: Lustre: OST es1-OST000a now serving dev (es1-OST000a/15fae56a-7dae-ba24-4423-347c0a118367), but will be in reco<br>
very for at least 5:00, or until 249 clients reconnect. During this time new clients will not be allowed to connect. Recovery progress can be<br>
 monitored by watching /proc/fs/lustre/obdfilter/es1-OST000a/recovery_status.<br>
Jul 18 09:33:45 IO-10 kernel: Lustre: es1-OST000a.ost: set parameter quota_type=ug<br>
Jul 18 09:33:45 IO-10 kernel: Lustre: Server es1-OST000a on device /dev/mpath/lun_11 has started<br>
Jul 18 09:33:45 IO-10 kernel: Lustre: 30790:0:(ldlm_lib.c:1226:check_and_start_recovery_timer()) es1-OST000a: starting req@ffff8101a6992c00<br>
 x5558026/t0 o8-><?>@<?>:0/0 lens 304/0 e 0 to 0 dl 1310999725 ref 1 fl Interpret:/0/0 rc -19/0<br>
Jul 18 09:33:45 IO-10 kernel: LustreError: 30789:0:(ldlm_lib.c:1619:target_send_reply_msg()) Skipped 2 previous similar messages<br>
Jul 18 09:33:45 IO-10 kernel: fsfilt_ldiskfs: no version for "ldiskfs_free_blocks" found: kernel tainted.<br>
Jul 18 09:33:45 IO-10 kernel: Lustre: Filtering OBD driver; <a href="http://www.lustre.org/" target="_blank">http://www.lustre.org/</a><br>
Jul 18 09:33:45 IO-10 kernel: Lustre: 31834:0:(filter.c:868:filter_init_server_data()) RECOVERY: service es1-OST000a, 249 recoverable clients<br>
, last_rcvd 469616249<br>
Jul 18 09:33:45 IO-10 kernel: Lustre: OST es1-OST000a now serving dev (es1-OST000a/15fae56a-7dae-ba24-4423-347c0a118367), but will be in reco<br>
very for at least 5:00, or until 249 clients reconnect. During this time new clients will not be allowed to connect. Recovery progress can be<br>
 monitored by watching /proc/fs/lustre/obdfilter/es1-OST000a/recovery_status.<br>
Jul 18 09:33:45 IO-10 kernel: Lustre: es1-OST000a.ost: set parameter quota_type=ug<br>
Jul 18 09:33:45 IO-10 kernel: Lustre: Server es1-OST000a on device /dev/mpath/lun_11 has started<br>
Jul 18 09:33:45 IO-10 kernel: Lustre: 30790:0:(ldlm_lib.c:1226:check_and_start_recovery_timer()) es1-OST000a: starting recovery timer<br>
Jul 18 09:33:45 IO-10 kernel: LustreError: 137-5: UUID 'es1-OST000b_UUID' is not available  for connect (no target)<br>
Jul 18 09:33:45 IO-10 kernel: LustreError: Skipped 4 previous similar messages<br>
Jul 18 09:33:45 IO-10 kernel: LustreError: 30792:0:(ldlm_lib.c:1619:target_send_reply_msg()) @@@ processing error (-19)  req@ffff8103185c9000<br>
 x215076358/t0 o8-><?>@<?>:0/0 lens 304/0 e 0 to 0 dl 1310999725 ref 1 fl Interpret:/0/0 rc -19/0<br>
Jul 18 09:33:45 IO-10 kernel: Lustre: 30794:0:(ldlm_lib.c:1567:target_queue_last_replay_reply()) es1-OST000a: 248 recoverable clients remain<br>
Jul 18 09:33:46 IO-10 kernel: Lustre: 30806:0:(ldlm_lib.c:1567:target_queue_last_replay_reply()) es1-OST000a: 247 recoverable clients remain<br>
Jul 18 09:33:46 IO-10 kernel: LustreError: 137-5: UUID 'es1-OST000e_UUID' is not available  for connect (no target)<br>
Jul 18 09:33:46 IO-10 kernel: LustreError: 30815:0:(ldlm_lib.c:1619:target_send_reply_msg()) @@@ processing error (-19)  req@ffff8102f093d000<br>
 x220133374/t0 o8-><?>@<?>:0/0 lens 304/0 e 0 to 0 dl 1310999726 ref 1 fl Interpret:/0/0 rc -19/0<br>
Jul 18 09:33:46 IO-10 kernel: LustreError: 30815:0:(ldlm_lib.c:1619:target_send_reply_msg()) Skipped 11 previous similar messages<br>
Jul 18 09:33:46 IO-10 kernel: LustreError: Skipped 14 previous similar messages<br>
Jul 18 09:33:46 IO-10 kernel: Lustre: 30889:0:(ldlm_lib.c:1567:target_queue_last_replay_reply()) es1-OST000a: 245 recoverable clients remain<br>
Jul 18 09:33:46 IO-10 kernel: Lustre: 30889:0:(ldlm_lib.c:1567:target_queue_last_replay_reply()) Skipped 1 previous similar message<br>
Jul 18 09:33:47 IO-10 kernel: LustreError: 137-5: UUID 'es1-OST000b_UUID' is not available  for connect (no target)<br>
Jul 18 09:33:47 IO-10 kernel: LustreError: 31004:0:(ldlm_lib.c:1619:target_send_reply_msg()) @@@ processing error (-19)  req@ffff8102fea35450<br>
 x33450807/t0 o8-><?>@<?>:0/0 lens 304/0 e 0 to 0 dl 1310999727 ref 1 fl Interpret:/0/0 rc -19/0<br>
Jul 18 09:33:47 IO-10 kernel: LustreError: 31004:0:(ldlm_lib.c:1619:target_send_reply_msg()) Skipped 47 previous similar messages<br>
Jul 18 09:33:47 IO-10 kernel: LustreError: Skipped 47 previous similar messages<br>
----------------------------------------------------------------------end messages ------------------------------------------------------------------------------------------<br>
<br>
I'm not seeing that Lustre is trying to recover at all. Any thoughts on where to go from here, Lustre (mounted at /scratch on clients) is starting to have problems cluster-wide.<br>
<br>
<br>
<br>
<div style="font-family:Tahoma;font-size:13px">
<div><font size="2">
<div>Best Regards,<br><font color="#888888">
--<br>
DaMiri Young<br>
System Engineer<br>
High Performance Computing Team<br>
CITC Academic Computing and User Services | UNT</font></div>
</font></div>
</div>
</div>
</div>
</div>

<br>_______________________________________________<br>
Lustre-discuss mailing list<br>
<a href="mailto:Lustre-discuss@lists.lustre.org">Lustre-discuss@lists.lustre.org</a><br>
<a href="http://lists.lustre.org/mailman/listinfo/lustre-discuss" target="_blank">http://lists.lustre.org/mailman/listinfo/lustre-discuss</a><br>
<br></blockquote></div><br>