Questions[errors](server)

My site: https://www.notfriendly.xyz/ (disabled CloudFlare) (See CloudFlare enabled at https://host.notfriendly.xyz) is failing to connect claiming a protocol error after enabling CloudFlare. Could someone tell me what is causing this? For the time being I disabeld their reverse proxy and the protectons.

My nginx ssl config is:

    https://50.16.136.91
 #ssl_protocols       TLSv1 TLSv1.1 TLSv1.2;
    ssl_protocols TLSv1.2;
    ssl_prefer_server_ciphers on;
    #ssl_ciphers        "ECDHE-RSA-AES256-GCM-SHA384:ECDHE-RSA-AES128-GCM-SHA25$
    ssl_ciphers AES256+EECDH:AES256+EDH:!aNULL;
    ssl_dhparam ssl/dhparam.pem;
    ssl_stapling on;
    ssl_stapling_verify on;
    ssl_session_timeout 10m;
    add_header Strict-Transport-Security "max-age=31536000; includeSubdomains; $
    add_header X-Frame-Options DENY;
    add_header X-Content-Type-Options nosniff;

I'm unsure what's causing the error.

CloudFlare is also stuck on "authorizing certificate".

It's disabled so hopefully site will be back soon.

What can I do to make CloudFlare work with my site?

EDIT: I showed a working URL and added a test to demonstate the error.

My Ubuntu servers ethernet interface that connectes to ISP's multiplexer shows errors. Here is the snapshot:

          RX packets:204564288 errors:3193970 dropped:0 overruns:0 frame:3138402
          TX packets:29305799 errors:38752 dropped:0 overruns:0 carrier:38762
          collisions:2205053 txqueuelen:1000

Ubuntu interface is capable of full duplex but it negotiates only half duplex connection. When I connected a different device (a router) to MUX, it also showed such errors. The bandwidth assigned is 50 mbps, but I get only 20 mbps. The ISP is reluctant to change their device (looks like a ethernet switch or hub) in the MUX. The ISP engineers blame that its fault at my side. But I checked with more than 3 devices, all showed errors. So, are there any tools for Linux which I can use to probe deep into the causes of those errors, or is there anything I can do to reconfigure my server's interface so as to get rid of those errors?

I'd like to prepend the vhost name in my ErrorLog and then pipe it into a program I wrote.

Is it possible to write Custom Error log format as it is with Access log?

My story starts out quite simply. I have a light-duty server, running Arch Linux, which stores most of its data on a RAID-1 composed of two SATA drives. It was working without any problems for about 4 months. Then, suddenly I started getting read errors on one of the drives. Always, the messages looked a lot like these:

Apr 18 00:20:15 hope kernel: [307085.582035] ata5.01: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
Apr 18 00:20:15 hope kernel: [307085.582040] ata5.01: failed command: READ DMA EXT
Apr 18 00:20:15 hope kernel: [307085.582048] ata5.01: cmd 25/00:08:08:6a:34/00:00:27:00:00/f0 tag 0 dma 4096 in
Apr 18 00:20:15 hope kernel: [307085.582050]          res 51/40:00:0c:6a:34/40:00:27:00:00/f0 Emask 0x9 (media error)
Apr 18 00:20:15 hope kernel: [307085.582053] ata5.01: status: { DRDY ERR }
Apr 18 00:20:15 hope kernel: [307085.582056] ata5.01: error: { UNC }
Apr 18 00:20:15 hope kernel: [307085.621301] ata5.00: configured for UDMA/133
Apr 18 00:20:15 hope kernel: [307085.640972] ata5.01: configured for UDMA/133
Apr 18 00:20:15 hope kernel: [307085.640986] sd 4:0:1:0: [sdd] Unhandled sense code
Apr 18 00:20:15 hope kernel: [307085.640989] sd 4:0:1:0: [sdd]  Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
Apr 18 00:20:15 hope kernel: [307085.640993] sd 4:0:1:0: [sdd]  Sense Key : Medium Error [current] [descriptor]
Apr 18 00:20:15 hope kernel: [307085.640998] Descriptor sense data with sense descriptors (in hex):
Apr 18 00:20:15 hope kernel: [307085.641001]         72 03 11 04 00 00 00 0c 00 0a 80 00 00 00 00 00 
Apr 18 00:20:15 hope kernel: [307085.641010]         27 34 6a 0c 
Apr 18 00:20:15 hope kernel: [307085.641020] sd 4:0:1:0: [sdd]  Add. Sense: Unrecovered read error - auto reallocate failed
Apr 18 00:20:15 hope kernel: [307085.641023] sd 4:0:1:0: [sdd] CDB: Read(10): 28 00 27 34 6a 08 00 00 08 00
Apr 18 00:20:15 hope kernel: [307085.641027] end_request: I/O error, dev sdd, sector 657746444
Apr 18 00:20:15 hope kernel: [307085.641035] ata5: EH complete
Apr 18 00:20:15 hope kernel: [307085.641672] md/raid1:md16: read error corrected (8 sectors at 657744392 on sdd1)
Apr 18 00:20:17 hope kernel: [307087.505082] md/raid1:md16: redirecting sector 657742336 to other mirror: sdd1

Each error complained of a different sector number, and was accompanied by a several-second delay for the user (me) accessing the disk.

I checked the smartctl output, and saw the following output (irrelevant parts clipped):

ID# ATTRIBUTE_NAME          FLAG     VALUE WORST THRESH TYPE      UPDATED  WHEN_FAILED RAW_VALUE
  1 Raw_Read_Error_Rate     0x002f   193   193   051    Pre-fail  Always       -       1606
  5 Reallocated_Sector_Ct   0x0033   194   194   140    Pre-fail  Always       -       0
196 Reallocated_Event_Count 0x0032   162   162   000    Old_age   Always       -       0
197 Current_Pending_Sector  0x0032   200   200   000    Old_age   Always       -       51

Looking back in the logs, I found that the errors had actually been happening for a few days, mostly during backups, but also frequently during very light use (meaning about every 5th time I tried to save a text file). I concluded that my disk was dying, that the RAID-1 was handling it appropriately, and that it was time to order a replacement disk. I ordered a new disk.

Much to my surprise, a day later, the errors... stopped. I had done nothing to fix them. I hadn't rebooted, hadn't taken the drive offline, nothing. But the errors just stopped.

At that point, curious to see whether the bad sectors were just in idle portions of the disk now, I took the disk out of the RAID, put it back in the RAID, and allowed it to complete the ensuing full resync. The resync completed without any errors, 9 hours later (2TB disks take a little while).

Also, the smartctl output has changed a bit, as follows:

ID# ATTRIBUTE_NAME          FLAG     VALUE WORST THRESH TYPE      UPDATED  WHEN_FAILED RAW_VALUE
  1 Raw_Read_Error_Rate     0x002f   193   193   051    Pre-fail  Always       -       1606
  5 Reallocated_Sector_Ct   0x0033   194   194   140    Pre-fail  Always       -       43
196 Reallocated_Event_Count 0x0032   162   162   000    Old_age   Always       -       38
197 Current_Pending_Sector  0x0032   200   200   000    Old_age   Always       -       0

So, the part of this that's weirding me out is, of course, "Since when do bad disks fix themselves?"

I suppose it's possible that a very small area of the drive spontaneously went bad, and that the drive simply took 3 days (!) before its sector reallocation code kicked in and it mapped some spare sectors over a bad area of the disk... But I can't say that I've ever seen that happen.

Has anyone else seen this kind of behavior? If so, what was your experience with the drive afterward? Did it happen again? Did the disk eventually fail completely? Or was it just an unexplained glitch that remained unexplained?

In my case, I already have the replacement drive (obtained under warranty), so I'll probably just replace the drive anyway. But I'd love to know if I misdiagnosed this somehow. If it helps, I have have complete 'smartctl -a' output from when the problem was happening. It's just a bit long, so I didn't post it here.

I've started seeing errors reported by LVM on certain Logical Volumes (and by Xen when attempting to create virtual machines on these LVs). But I've run tests on the disk, and can't see any hardware problems.

We're running a XEN/Linux (Debian Lenny) box here, running off a single SATA disk managed with LVM2. It's been in and running for more than a year, with the only major changes being recent apt-get upgrade of the kernel.

# uname -a
Linux hostname 2.6.26-2-xen-amd64 #1 SMP Thu Sep 16 16:32:15 UTC 2010 x86_64 GNU/Linux

The errors appear like this:

# vgck
/dev/dm-20: read failed after 0 of 4096 at 0: Input/output error

And then when I try to start the VM which uses that LV for its C-drive (it's a Windows virtual machine), the VM refuses to start and I see this at the end of the /var/log/xen/qemu-dm-*.log log file:

...
Register xen platform.
Done register platform.
raw_read(6:/dev/vgroup/newvm-cdrive, 0, 0x7fff02bca520, 512) [20971520] read failed -1 : 5 = Input/output error
I/O request not ready: 0, ptr: 0, port: 0, data: 0, count: 0, size: 0
raw_read(6:/dev/vgroup/newvm-cdrive, 0, 0x12dfff0, 512) [20971520] read failed -1 : 5 = Input/output error

This first happened on 2 VMs whose disk was based on a snapshot of a third, original VM. I nuked the 2 LVs and recreated them (again by snapshotting the same, original VM's LV), and they've been fine since.

However, today I attempted to create a new VM. I snapshotted the same, orginal VM's LV (lvcreate -L500M --snapshot --name newvm-cdrive /dev/vgroup/original-cdrive), and created the new VM. It initially worked, but after shutting down the VM once, it refuses to start up again, with the errors shown above.

My obvious first guess would be physical problems with the drive, but smartmon does not report anything:

# smartctl -t long /dev/sda
# [later]
# smartctl -l selftest /dev/sda
smartctl version 5.38 [x86_64-unknown-linux-gnu] Copyright (C) 2002-8 Bruce Allen
Home page is http://smartmontools.sourceforge.net/

=== START OF READ SMART DATA SECTION ===
SMART Self-test log structure revision number 1
Num  Test_Description    Status                  Remaining  LifeTime(hours)  LBA_of_first_error
# 1  Extended offline    Completed without error       00%         1         -
# 2  Short offline       Completed without error       00%         0         -

Also, not getting any errors from badblocks.

I've tried running vgck and pvck:

# vgck vgroup -v
    Using volume group(s) on command line
    Finding volume group "vgroup"
  /dev/dm-20: read failed after 0 of 4096 at 0: Input/output error

# pvck /dev/sda2
  Found label on /dev/sda2, sector 1, type=LVM2 001
  Found text metadata area: offset=4096, size=192512

Have found a few references to this error message ("read failed after 0 of 4096 at...") on the Interwebs, but nothing which seems to apply to my situation.

Any ideas?

Update: As requested, below is output of lvdisplay and ls -l. Running out of COW space is plausible. How do I tell?

# lvdisplay /dev/vgroup/newvm-cdrive
  /dev/dm-20: read failed after 0 of 4096 at 0: Input/output error
  --- Logical volume ---
  LV Name                /dev/vgroup/newvm-cdrive
  VG Name                vgroup
  LV UUID                jiarxt-q2NO-SyIf-5FrW-I9iq-mNEQ-iwS4EH
  LV Write Access        read/write
  LV snapshot status     INACTIVE destination for /dev/vgroup/original-cdrive
  LV Status              available
  # open                 0
  LV Size                10.00 GB
  Current LE             2560
  COW-table size         200.00 MB
  COW-table LE           50
  Snapshot chunk size    4.00 KB
  Segments               1
  Allocation             inherit
  Read ahead sectors     auto
  - currently set to     256
  Block device           254:20

# ls -l /dev/dm-20
brw-rw---- 1 root disk 254, 20 2010-10-11 15:02 /dev/dm-20

And here's fdisk -l.

# fdisk -l /dev/sda

Disk /dev/sda: 160.0 GB, 160000000000 bytes
255 heads, 63 sectors/track, 19452 cylinders
Units = cylinders of 16065 * 512 = 8225280 bytes
Disk identifier: 0x00000080

   Device Boot      Start         End      Blocks   Id  System
/dev/sda1   *           1          31      248976   83  Linux
/dev/sda2              32       19452   155999182+  8e  Linux LVM