ehci_hdc driver bug

지난달에 있었던 일이다.

여느날처럼 서버들의 로그를 확인하던 중에 아래와 같은 로그를 발견했다.

Aug  8 12:06:27 s9 kernel: usb 1-1.2: reset full speed USB device number 29 using ehci_hcd

Aug  8 12:06:40 s9 kernel: usb 1-1.2: USB disconnect, device number 29

Aug  8 12:06:40 s9 kernel: usb 1-1.2: new full speed USB device number 30 using ehci_hcd

Aug  8 12:06:40 s9 kernel: usb 1-1.2: New USB device found, idVendor=0557, idProduct=2221

Aug  8 12:06:40 s9 kernel: usb 1-1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=0

Aug  8 12:06:40 s9 kernel: usb 1-1.2: Product: Hermon USB hidmouse Device

Aug  8 12:06:40 s9 kernel: usb 1-1.2: Manufacturer: Winbond Electronics Corp

Aug  8 12:06:40 s9 kernel: usb 1-1.2: configuration #1 chosen from 1 choice

Aug  8 12:06:40 s9 kernel: input: Winbond Electronics Corp Hermon USB hidmouse Device as /devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.2/1-1.2:1.0/input/input57

Aug  8 12:06:40 s9 kernel: generic-usb 0003:0557:2221.0037: input,hidraw0: USB HID v1.00 Mouse [Winbond Electronics Corp Hermon USB hidmouse Device] on usb-0000:00:1a.0-1.2/input0

Aug  8 12:06:40 s9 kernel: input: Winbond Electronics Corp Hermon USB hidmouse Device as /devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.2/1-1.2:1.1/input/input58

Aug  8 12:06:40 s9 kernel: generic-usb 0003:0557:2221.0038: input,hidraw1: USB HID v1.00 Keyboard [Winbond Electronics Corp Hermon USB hidmouse Device] on usb-0000:00:1a.0-1.2/input1

Aug  8 12:06:45 s9 kernel: usb 1-1.2: USB disconnect, device number 30

Aug  8 12:06:46 s9 kernel: usb 1-1.2: new full speed USB device number 31 using ehci_hcd

Aug  8 12:06:46 s9 kernel: usb 1-1.2: New USB device found, idVendor=0557, idProduct=2221

Aug  8 12:06:46 s9 kernel: usb 1-1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=0

Aug  8 12:06:46 s9 kernel: usb 1-1.2: Product: Hermon USB hidmouse Device

Aug  8 12:06:46 s9 kernel: usb 1-1.2: Manufacturer: Winbond Electronics Corp

Aug  8 12:06:46 s9 kernel: usb 1-1.2: configuration #1 chosen from 1 choice

Aug  8 12:06:46 s9 kernel: input: Winbond Electronics Corp Hermon USB hidmouse Device as /devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.2/1-1.2:1.0/input/input59

Aug  8 12:06:46 s9 kernel: generic-usb 0003:0557:2221.0039: input,hidraw0: USB HID v1.00 Mouse [Winbond Electronics Corp Hermon USB hidmouse Device] on usb-0000:00:1a.0-1.2/input0

Aug  8 12:06:46 s9 kernel: input: Winbond Electronics Corp Hermon USB hidmouse Device as /devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.2/1-1.2:1.1/input/input60

Aug  8 12:06:46 s9 kernel: generic-usb 0003:0557:2221.003A: input,hidraw1: USB HID v1.00 Keyboard [Winbond Electronics Corp Hermon USB hidmouse Device] on usb-0000:00:1a.0-1.2/input1

편의상 오늘 발생한 로그로 대체한다. 날짜만 다를 뿐 내용은 같다.

로그를 살펴보자. 마우스와 키보드가 연결되었다는 로그인 것 같지 않은가?

위 로그를 발견하고 가슴이 철렁 내려 앉는 기분이었다.

'서버는 IDC에 모두 들어가 있는데 누가 그 서버에 마우스랑 키보드를 연결한 거지?'

로그에는 분명히 USB 포트에 마우스와 키보드가 연결되었다고 되어 있다.

'헐...IDC센터에 스파이가 있나?'

얼른 IDC센터에 전화를 걸었다. 현재 상황을 설명하자 IDC센터의 직원도 당황하는 기색이다. 고객의 서버에 서버를 컨트롤 할 수 있는 마우스와 키보드가 연결되었다니 당황할 수 밖에.

IDC센터에는 CCTV가 설치되어 있다. 예전에 KT IDC에 들어갈 일이 있었는데 출입절차도 상당히 까다로웠고 구석구석 설치되어 있는 CCTV를 본적이 있다. 다행히 회사가 이용하는 IDC센터에도 CCTV가 있다고 했다. 마우스와 키보드가 연결된 시간을 알려주고 해당시간대의 CCTV확인을 요청했다.

그.런.데!

그 시간대에 문제가 발생한 서버에 접근한 사람이 없다고 한다. CCTV는 사람의 출입이 감지되면 작동하게 되어있는 센서형 CCTV였는데 센서반응이 없었다고 한다. 그 말에 나도 당황하고 그 말을 전해주는 IDC센터의 직원도 당황해하고 있는 눈치다. 아무도 서버에 접근하지 않았다면 귀신이 마우스와 키보드를 꽂았단 말인가?

몇일동안 다방면으로 조사했으나 사람의 접근흔적은 발견 할 수 없었고 같은 문제가 재발하지 않은데다가 결정적으로 일이 많이 바빠지는 바람에 그냥저냥 넘어가게 됐다.

그렇게 서버의 무사안녕이 시작되나 했으나 이틀전부터 또 로그가 나타나기 시작했다. 이번에는 지난번과 다른 서버...또다시 발등에 불이 떨어졌다. 다시 IDC센터에 연락하고 이번에는 반드시 원인을 찾겠다는 생각으로 온갖 자료를 다 찾아보기 시작했다.

그렇게 지난 이틀동안 고생한 결과, 드디어 오늘 그 원인을 알아냈다!

원인은 바로 ... 

다음 포스팅에...

......라고 하면 테러를 당할 것 같다 -_-;결론부터 이야기하자면 이 포스팅의 제목이다. 바로 ehci_hdc driver bug! ehci_hdc는 usb 포트라고 생각하면 될 것 같다. 이 포트의 특징은 usb의 speed를 높이려고 한다는 것이다. 로그의 첫째줄을 보면

reset full speed USB device number 29 using ehci_hcd

라는 부분이 있는데 이 부분이 바로 ehci_hdc포트가 usb의 속도를 높이려고 하는 부분이다. 다시 로그를 살펴보자. 두번째 줄에 

USB disconnect, device number 29

라는 로그가 보일 것이다. 지금 현재 usb포트에는 아무것도 꽂혀있지 않기 때문에 접속을 끊었다. 여기까지는 정상적인 로그라고 할 수 있다. 문제가 되는 부분은 그 아래쪽 로그들이다. disconnect 시킨 다음 30번 넘버를 부여하면서 새로운 device를 찾아 ehci_hdc를 이용하게끔 한다. vendor와 Product, SerialNumber까지 명시되어 있어서 정말 USB포트를 사용하는 것 처럼 보인다.

하지만 자세히보면 Mount나 Unmount가 보이지 않는다.마우스나 키보드가 정상적으로 연결되면 로그에 Mount가 되었다는 메세지가 보인다.

Mount mouse /dev/sda

대략 이렇게 나올거다. Mount나 Unmount 메세지가 보이지 않으면 ehci_hdc driver bug를 의심해 볼 필요성이 있다. 위 로그를 보면 usb포트에 마우스와 키보드가 연결되었다는 메세지만 있을 뿐 어디에도 Mount나 Unmount 되었다는 메세지는 없다.

그럼 왜 이런 문제가 발생하는 것일까?

사실 이 문제를 겪어 본 SE들이 그렇게 많지는 않을거라 생각한다. 이유는 이 문제가 발생하기 위한 전제조건이 까다롭기 때문인데 

1. 서버를 설치(혹은 OS재설치)한다.

2. echi_hdc driver를 사용한다.(이건 뭐 거의 다 해당될 듯...)

3. 서버를 설치할 때 사용한 마우스와 키보드를 제거한다.(IDC에서는 보통 아무것도 연결하지 않고 이슈가 발생할 때에만 마우스나 키보드를 연결한다.)문제가 되는 로그에 나타나는 마우스와 키보드는 이때 사용한 마우스와 키보드이다. 설치 시 사용한 마우스와 키보드를 알아보려면 

cat /var/log/dmesg

를 치면 된다. dmesg는 부팅메세지를 가지고 있는 로그이다.

4. 서버 재부팅을 오랫동안 하지 않는다.(이 기간은 정해진 것이 아닌 것 같다. 또한 ehci_hdc driver에 이상이 발생하지 않는다면 해당 문제를 겪을 가능성은 0%다.)

5. ehci_hdc driver에 bug가 발생한다.

위 다섯가지 조건을 모두 만족시켜야 문제가 발생한다. 까다로운 놈이다.

문제의 해결방법은 간단하다.

1. 재부팅을 한다.

2. 좀 더 확실하게 하기 위해 ehci_hdc driver를 disabled 시킨 다음 재부팅 한다.

   - 명령어 : echo -n "0000:00:1a.0" > /sys/bus/pci/drivers/ehci_hcd/unbind

   * CentOS 6.4기준이다. Ubuntu나 fedora등은 잘 모르니 패스한다.

자, 위의 글들을 보기 싫어서 스크롤을 내려버린 사람들을 위한 간단 요약을 하겠다.

1. ehci_hdc driver usb포트 버그 있음. usb에 연결하지도 않았는데 마우스랑 키보드 연결했다고 함.

2. 재부팅 하거나 ehci_hdc driver을 disable한 다음 재부팅 하면 해결 됨.

핵심만 요약했으나 이해가능 하리라 생각한다. 오늘 포스팅은 여기서 끝.