alirz1 Posted August 24, 2016 #1 Posted August 24, 2016 Hello, I recently wiped my xpenology NAS clean and wanted to do a brand new setup from scratch. Once i did that three days ago. Its gone into this strange mode where it has become unresponsive, ping works but no other service is working. I can sometimes log into the DSM but cant really do anything, its like a ghost web process is making the DSM run and thats about it. I then looked into /var/log/messages and noticed the following: Aug 24 08:37:45 nas kernel: [39206.420031] ------------[ cut here ]------------ Aug 24 08:37:45 nas kernel: [39206.420039] WARNING: at drivers/ata/libata-core.c:5428 ata_qc_issue+0x2a6/0x3e0() Aug 24 08:37:45 nas kernel: [39206.420145] CPU: 1 PID: 21689 Comm: sshd Tainted: P C O 3.10.35 #1 Aug 24 08:37:45 nas kernel: [39206.420147] Hardware name: /DQ45EK, BIOS CBQ4510H.86A.0133.2011.0810.1010 08/10/2011 Aug 24 08:37:45 nas kernel: [39206.420149] ffffffff8151f517 0000000000000000 ffffffff81039c9a ffff88013164c000 Aug 24 08:37:45 nas kernel: [39206.420152] 0000000000000003 ffff88013164dc50 ffffffff813b7b50 ffff88013164c000 Aug 24 08:37:45 nas kernel: [39206.420155] ffffffff813b0ad6 ffff880131662a80 ffff88013164c218 0000000000000000 Aug 24 08:37:45 nas kernel: [39206.420158] Call Trace: Aug 24 08:37:45 nas kernel: [39206.420163] [] ? dump_stack+0xd/0x17 Aug 24 08:37:45 nas kernel: [39206.420168] [] ? warn_slowpath_common+0x6a/0xa0 Aug 24 08:37:45 nas kernel: [39206.420171] [] ? ata_scsi_set_sense.constprop.33+0x30/0x30 Aug 24 08:37:45 nas kernel: [39206.420174] [] ? ata_qc_issue+0x2a6/0x3e0 Aug 24 08:37:45 nas kernel: [39206.420177] [] ? ata_scsi_rw_xlat+0x168/0x210 Aug 24 08:37:45 nas kernel: [39206.420180] [] ? ata_scsi_set_sense.constprop.33+0x30/0x30 Aug 24 08:37:45 nas kernel: [39206.420183] [] ? ata_scsi_translate+0x9f/0x170 Aug 24 08:37:45 nas kernel: [39206.420186] [] ? ata_scsi_queuecmd+0x1eb/0x460 Aug 24 08:37:45 nas kernel: [39206.420190] [] ? internal_add_timer+0x18/0x50 Aug 24 08:37:45 nas kernel: [39206.420194] [] ? scsi_dispatch_cmd+0xd1/0x340 Aug 24 08:37:45 nas kernel: [39206.420197] [] ? scsi_request_fn+0x2d4/0x4b0 Aug 24 08:37:45 nas kernel: [39206.420201] [] ? __blk_run_queue+0x2a/0x40 Aug 24 08:37:45 nas kernel: [39206.420204] [] ? queue_unplugged.isra.58+0xe/0x30 Aug 24 08:37:45 nas kernel: [39206.420206] [] ? blk_flush_plug_list+0x1b9/0x210 Aug 24 08:37:45 nas kernel: [39206.420209] [] ? blk_finish_plug+0xb/0x30 Aug 24 08:37:45 nas kernel: [39206.420213] [] ? __do_page_cache_readahead+0x1bd/0x250 Aug 24 08:37:45 nas kernel: [39206.420216] [] ? ra_submit+0x1c/0x30 Aug 24 08:37:45 nas kernel: [39206.420219] [] ? filemap_fault+0x229/0x480 Aug 24 08:37:45 nas kernel: [39206.420223] [] ? __do_fault+0x6e/0x4f0 Aug 24 08:37:45 nas kernel: [39206.420226] [] ? handle_pte_fault+0xab/0x9a0 Aug 24 08:37:45 nas kernel: [39206.420229] [] ? kmem_cache_alloc+0xd8/0xe0 Aug 24 08:37:45 nas kernel: [39206.420232] [] ? __do_page_fault+0x1af/0x460 Aug 24 08:37:45 nas kernel: [39206.420236] [] ? alloc_file+0x26/0xe0 Aug 24 08:37:45 nas kernel: [39206.420239] [] ? sock_alloc_file+0x9a/0x130 Aug 24 08:37:45 nas kernel: [39206.420243] [] ? __fd_install+0x23/0x60 Aug 24 08:37:45 nas kernel: [39206.420246] [] ? SyS_socketpair+0x152/0x210 Aug 24 08:37:45 nas kernel: [39206.420249] [] ? page_fault+0x28/0x30 Aug 24 08:37:45 nas kernel: [39206.420252] ---[ end trace 28d794b310603a79 ]--- One thing i want to point out is that (another thread was opened but got no help there) during the xpenology boot process, it hangs at the "ata_piix" process in state BUSY for at least 1 minute. After the boot has completed, the messages log shows a lot of entries like " Aug 24 09:12:41 nas kernel: [ 5.225718] want_idx 0 index 1. delay and reget Aug 24 09:12:41 nas kernel: [ 6.225007] want_idx 0 index 1 Aug 24 09:12:41 nas kernel: [ 6.225011] want_idx 0 index 1. delay and reget Aug 24 09:12:41 nas kernel: [ 7.225004] want_idx 0 index 1 Aug 24 09:12:41 nas kernel: [ 7.225006] want_idx 0 index 1. delay and reget Aug 24 09:12:41 nas kernel: [ 8.225005] want_idx 0 index 1 Aug 24 09:12:41 nas kernel: [ 8.225006] want_idx 0 index 1. delay and reget Aug 24 09:12:41 nas kernel: [ 9.225004] want_idx 0 index 1 Aug 24 09:12:41 nas kernel: [ 9.225006] want_idx 0 index 1. delay and reget Not sure if its relates somehow...I think i only started noticing these error when i added two NEW additional drives to the system. Previously i only had two drives. Now im running two disk groups with 2disks in each group with in RAID 0. Possibly Xpenelogy having issue support the ata controller with 4 drives or something? I have done a smart check on all my drives and they are fine.
TomS. Posted August 24, 2016 #2 Posted August 24, 2016 I see a couple of potential investigation points: Starting with the Linux ATA wiki [1], ata-piix is for an Intel ICH in IDE emulation mode. ata_qc_issue, from your 1st message log, is preparing a command to issue to a device from [2] I'd address the IDE emulation issue first. Verify that the BIOS is set to SATA native (AHCI) for all storage controllers and not any of the legacy or compatibility modes. * * Caution: changing controller modes is a _destructive_ action. It will invalidate all disk contents. You _must_ repartition / reformat / reinstall DSM. If indeed the storage controllers were in Emulation, then changing the mode will change the driver to ahci from ata_piix. If the system was encountering a piix bug, now it has been avoided by using a different driver. Judging from your previous post, there is also a 3ware hardware RAID controller in this system. Because of the invalid superblock message in your previous post, it appears that at least some drives are connected to the 3ware controller? May I ask you to report the following info: Intel Motherboard model # and BIOS revision mainboard SATA controller mode from BIOS Manufacturer and model of any add-in controller card Add-in card firmware controller mode drive make, model, firmware revision and SATA connection point (mainboard port # or add-in port #) [1] https://ata.wiki.kernel.org/index.php/Main_Page [2] https://kernel.org/doc/htmldocs/libata/ ... issue.html
alirz1 Posted August 24, 2016 Author #3 Posted August 24, 2016 Thank you very much for your very detail and informing post. Yes you were indeed correct on the SATA mode. It was set to IDE. instead of being AHCI.I'm not sure when this got changed because i've been using this setup for several months and only started experiencing problems when i started using a RAID 0 setup that was done in DSM. Here is the hard and other info: Hardware: Intel motherboard DQ45EK, BIOS CBQ4510H.86A.0133.2011.0810.1010 08/10/2011 (its a pretty old board). CPU: Intel core 2 duo (2.4 GHZ i believe) 4GB ram No add in cards. HDD: 4x3TB Sata Western digital RED. The board has 4 SATA ports. The mother board also support RAID but im not using it. Its very likely that two of the four ports are for the sata controller as is usually the case. however that shouldn't be causing an issue unless the current IDE SATA mode is having some problem with that. I will soon, switch to AHCI and start everything from scratch.
alirz1 Posted August 24, 2016 Author #4 Posted August 24, 2016 So i switched the SATA mode to ACHI and have rebuilt the xpenology from scratch. Good news is that the ata_piix error is gone. The boot process doesnt hang at ata_piix BUSY now!!!! awesome. Also, no more of those " WANT IDX INDEX" error in the messages log.. Also Awesome. For now i've only connected two hdds to the system on sata port 1+2. The other two drives are unplugged. Real test would e to use the system like this for a day and see if it freezes. hopefully not as i dont see why it should now. There are no panics in the log anymore. So in a day or two ill connect the other two drives and set them up and report back.
TomS. Posted August 25, 2016 #5 Posted August 25, 2016 So i switched the SATA mode to ACHI and have rebuilt the xpenology from scratch. Good news is that the ata_piix error is gone. The boot process doesnt hang at ata_piix BUSY now!!!! awesome. Also, no more of those " WANT IDX INDEX" error in the messages log.. Also Awesome. Wonderful, glad it worked. I suspect you'll experience much improved disk performance. I've verified that you do have the latest BIOS for that board. Don't see anything else to change in that regard. With no add in cards, I wonder why those 3ware lines were in the messages log? Doesn't seem relevant now. Best of luck on your new system. //TomS.
alirz1 Posted August 25, 2016 Author #6 Posted August 25, 2016 Ok i still do see the following error after very reboot of the xpenology. I havent experienced any problems with the system so i dont know if these errors are "normal" for my box or not Aug 24 22:09:28 nas root: == DSM finished boot up == Aug 24 22:09:29 nas transmission-daemon[21868]: UDP Failed to set receive buffer: requested 4194304, got 425984 (tr-udp.c:84) Aug 24 22:09:29 nas transmission-daemon[21868]: UDP Failed to set send buffer: requested 1048576, got 425984 (tr-udp.c:95) Aug 24 22:09:31 nas kernel: [ 32.126188] pin 45 is protected by driver. Aug 24 22:09:31 nas kernel: [ 32.126270] BUG: unable to handle kernel paging request at 0000000000002c81 Aug 24 22:09:31 nas kernel: [ 32.126273] IP: [] syno_mv_9235_disk_led_set+0x27/0xd0 Aug 24 22:09:31 nas kernel: [ 32.126280] PGD 1336d1067 PUD 130641067 PMD 0 Aug 24 22:09:31 nas kernel: [ 32.126283] Oops: 0000 [#1] SMP Aug 24 22:09:31 nas kernel: [ 32.126363] CPU: 0 PID: 18698 Comm: scemd Tainted: P C O 3.10.35 #1 Aug 24 22:09:31 nas kernel: [ 32.126365] Hardware name: /DQ45EK, BIOS CBQ4510H.86A.0133.2011.0810.1010 08/10/2011 Aug 24 22:09:31 nas kernel: [ 32.126367] task: ffff88013623d080 ti: ffff880135e44000 task.ti: ffff880135e44000 Aug 24 22:09:31 nas kernel: [ 32.126368] RIP: 0010:[] [] syno_mv_9235_disk_led_set+0x27/0xd0 Aug 24 22:09:31 nas kernel: [ 32.126372] RSP: 0018:ffff880135e47d18 EFLAGS: 00010202 Aug 24 22:09:31 nas kernel: [ 32.126373] RAX: ffff880132b32800 RBX: 0000000000000000 RCX: ffff880132b32b30 Aug 24 22:09:31 nas kernel: [ 32.126375] RDX: 0000000000000001 RSI: 0000000000000000 RDI: ffff880132b32800 Aug 24 22:09:31 nas kernel: [ 32.126376] RBP: 0000000000000000 R08: 0000000000000009 R09: 0000000000000001 Aug 24 22:09:31 nas kernel: [ 32.126378] R10: 00000000f7784430 R11: 0000000000000000 R12: ffff8801313336c0 Aug 24 22:09:31 nas kernel: [ 32.126379] R13: 0000000000000009 R14: 0000000000000001 R15: 0000000000000000 Aug 24 22:09:31 nas kernel: [ 32.126381] FS: 0000000000000000(0000) GS:ffff88013bc00000(0063) knlGS:00000000f49e0b70 Aug 24 22:09:31 nas kernel: [ 32.126382] CS: 0010 DS: 002b ES: 002b CR0: 0000000080050033 Aug 24 22:09:31 nas kernel: [ 32.126384] CR2: 0000000000002c81 CR3: 000000013065c000 CR4: 00000000000007f0 Aug 24 22:09:31 nas kernel: [ 32.126385] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 Aug 24 22:09:31 nas kernel: [ 32.126387] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400 Aug 24 22:09:31 nas kernel: [ 32.126388] Stack: Aug 24 22:09:31 nas kernel: [ 32.126389] 0000000000000008 ffffffffa0c85c78 ffffffffffffffff 00000000f49e0038 Aug 24 22:09:31 nas kernel: [ 32.126392] ffff8801313336c0 ffffffffa0c825a4 ffffffff81862788 ffff880135e47de0 Aug 24 22:09:31 nas kernel: [ 32.126394] ffff8801362b9000 0000000000000009 00000000ffffff9c 00000000ffffff9c Aug 24 22:09:31 nas kernel: [ 32.126397] Call Trace: Aug 24 22:09:31 nas kernel: [ 32.126403] [] ? SetSCSIHostLedStatusBy9235GPIOandAHCISGPIO+0x68/0x100 [bromolow_synobios] Aug 24 22:09:31 nas kernel: [ 32.126406] [] ? synobios_ioctl+0xe54/0x1090 [bromolow_synobios] Aug 24 22:09:31 nas kernel: [ 32.126411] [] ? filename_lookup+0x2c/0xb0 Aug 24 22:09:31 nas kernel: [ 32.126413] [] ? getname_flags.part.31+0x84/0x130 Aug 24 22:09:31 nas kernel: [ 32.126416] [] ? user_path_at_empty+0xa0/0x120 Aug 24 22:09:31 nas kernel: [ 32.126420] [] ? sysfs_getattr+0x4b/0x60 Aug 24 22:09:31 nas kernel: [ 32.126422] [] ? dput+0x22/0x1b0 Aug 24 22:09:31 nas kernel: [ 32.126426] [] ? compat_sys_ioctl+0x1e7/0x1500 Aug 24 22:09:31 nas kernel: [ 32.126429] [] ? sys32_stat64+0x10/0x30 Aug 24 22:09:31 nas kernel: [ 32.126433] [] ? sysenter_dispatch+0x7/0x21 Aug 24 22:09:31 nas kernel: [ 32.126434] Code: 1f 44 00 00 53 0f b7 ff 89 f3 e8 25 7a f9 ff 48 85 c0 48 89 c7 0f 84 a0 00 00 00 48 8b 90 f8 04 00 00 48 Aug 24 22:09:31 nas kernel: [ 32.126455] RIP [] syno_mv_9235_disk_led_set+0x27/0xd0 Aug 24 22:09:31 nas kernel: [ 32.126458] RSP Aug 24 22:09:31 nas kernel: [ 32.126459] CR2: 0000000000002c81 Aug 24 22:09:31 nas kernel: [ 32.126462] ---[ end trace 3c9d101388eea937 ]--- Seems like DSM wants to set the LED status for the drive status but obviously i have no leds here. So im thinking this is somewhat normal and can be ignored safely?
TomS. Posted September 1, 2016 #7 Posted September 1, 2016 The first two lines "UDP failed to set…" appear related to an installed program, "Transmission". I'm inclined to agree with your judgment on the kernel lines starting @ 09:31. I'm definitely not a developer or hardware debugger, so don't put too much faith in that agreement. Perhaps you could do a little research on the Intel mainboard you have and the chipset, particularly the southbridge. Compare that with your dmesg output. See if there are more recent drivers than what shipped with the last boot update. //TS
Recommended Posts