2016년 10월 정기 점검

데이터서비스팀은 10월 정기점검일을 맞아 메인 서비스 DB로 운영중인 Windows Server 2012 R2, SQL Server 2012 2기를 업데이트 및 리부팅 작업을 진행하였습니다. 강력한 IO 성능을 위해 도입한 FusionIO 의 점검도 하고, Table 들의 인덱스도 손보고 각종 점검도 했습니다. 간단한 서비스 테스트를 진행한후 서비스를 오픈했지요. 그런데 갑자기 로그시스템에 에러가 조금씩 보이기 시작하고 대쉬보드가 빨간색으로 바뀝니다.

살펴보니 DB connection 이 제대로 맺히지 않고 끊기는 문제들이 발생하고 있는데, 모든 connection 에 에러가 있는 것도 아니고 좀 이상합니다.

노트북에서 python 을 사용해서 테스트를 해봤습니다.

$ while true; do run_sql.py "select 1"; done

10 번에 한번쯤은 exception 이 발생했습니다.

pymssql.OperationalError: (20017,
‘DB-Lib error message 20017, severity 9: Unexpected EOF from the server
DB-Lib error message 20002, severity 9: Adaptive Server connection failed’)

Windows Event Log 에는 다음과 같은 에러들이 무수히 찍혀있네요.

Event ID 36888.
Schannel Error – The following fatal alert was generated: 20.
The internal error state is 960

폭풍 검색을 해보지만 딱 맞는게 잘 안보입니다. 하지만 전반적으로 TLS에 관련된 이야기, negotiation 과정에서의 에러 등등의 내용이 검색되었습니다.

sql-server-freetds-freetds-fails-to-connect-to-sql-server-after-recent-windows-patches-and-tls1-being-disabled

그리고 이런 글도 보입니다. 윈도에서 특정 패치를 롤백하라는 내용입니다. 디비서버라 건드리기 무서워서 이건 최후의 수단으로 생각하고 미뤄두었습니다. (게다가 글에 언급된 패치번호도 없어서 설치된 핫픽스들을 일일이 내용파악해야 했죠.)

어떤 에러일까?

pymssql 에서 출력하는 에러만으로는 뭔가 부족해서 또 구글신의 도움을 받습니다. freetds 라이브러리는 로그를 남기는 기능이 있어서 자세한 상황을 볼 수 있습니다. 이 로그는 append 되지 않고 한번의 세션에 대한 로그라서 에러가 남는 상황에서 딱 봐줘야 합니다. ~/.freetds.conf 파일을 작성하고, 

[global]
tds version = 7.4
dump file = /Users/nazgul33/tds.dump.log
debug flags = 0x6fff

shell script 에서 에러가 난 경우 바로 빠져나오도록 테스트했습니다. 

$ while true; do python dbconn_test.py; if [ $? -ne 0 ] ; then break; fi; done
1
1
....
1
Traceback (most recent call last):
  File "dbconn_test.py", line 42, in <module>
    conn_test()
  File "dbconn_test.py", line 20, in conn_test
    conn = pymssql.connect(config.server, config.user, config.password, "SbSvc")
  File "pymssql.pyx", line 641, in pymssql.connect (pymssql.c:10824)
pymssql.OperationalError: (20017, 'DB-Lib error message 20017, severity 9:\nUnexpected EOF from the server\nDB-Lib error message 20002, severity 9:\nAdaptive Server connection failed\n')

에러로그를 살펴봅니다. /Users/nazgul33/tds.dump.log 

09:38:16.785368 (net.c:1201):in tds_pull_func
09:38:16.785379 (net.c:1214):have 0
09:38:16.785386 (net.c:1218):before read
09:38:16.789812 (util.c:156):Changed query state from IDLE to DEAD
09:38:16.789844 (util.c:331):tdserror(0x7fd0c144ab20, 0x7fd0c1433e40, 20017, 0)
09:38:16.789869 (dblib.c:7929):dbperror(0x7fd0c1450460, 20017, 0)
09:38:16.789888 (dblib.c:7981):20017: "Unexpected EOF from the server"
09:38:16.789909 (dblib.c:8002):"Unexpected EOF from the server", client returns 2 (INT_CANCEL)
09:38:16.789917 (util.c:361):tdserror: client library returned TDS_INT_CANCEL(2)
09:38:16.789925 (util.c:384):tdserror: returning TDS_INT_CANCEL(2)
09:38:16.789999 (net.c:1517):handshake failed
09:38:16.790009 (login.c:466):login packet rejected
09:38:16.790016 (util.c:331):tdserror(0x7fd0c144ab20, 0x7fd0c1433e40, 20002, 0)
09:38:16.790023 (dblib.c:7929):dbperror(0x7fd0c1450460, 20002, 0)
09:38:16.790033 (dblib.c:7981):20002: "Adaptive Server connection failed"
09:38:16.790044 (dblib.c:8002):"Adaptive Server connection failed", client returns 2 (INT_CANCEL)
09:38:16.790052 (util.c:361):tdserror: client library returned TDS_INT_CANCEL(2)
09:38:16.790058 (util.c:384):tdserror: returning TDS_INT_CANCEL(2)
09:38:16.790073 (dblib.c:1443):dbclose(0x7fd0c1450460)
09:38:16.790080 (dblib.c:258):dblib_del_connection(0x10b45dea0, 0x7fd0c1433e40)
09:38:16.790092 (mem.c:615):tds_free_all_results()
09:38:16.790107 (dblib.c:305):dblib_release_tds_ctx(1)
09:38:16.790119 (dblib.c:5882):dbfreebuf(0x7fd0c1450460)
09:38:16.790127 (dblib.c:739):dbloginfree(0x7fd0c1446fa0)

SQL server 쪽에서 연결을 강제로 끊은 상황입니다. 아마도 session negotiation 중에 에러상황이라고 판단하고 끊었다고 생각됩니다. 암호화 session 이 문제가 되었거나 tds 프로토콜 핸들링의 문제일 것이라고 더 확신하게 됩니다.

내 노트북에서 테스트해보자

서버가 업데이트되었으니 클라이언트도 업데이트해보기로 결심했습니다. 제 노트북 환경 ( El Capitan, Home brew ) 에서 일단 테스트해봐야겠죠. pymssql, freetds, openssl 을 업데이트합니다.

일단 다 삭제!

$ pip uninstall pymssql
$ brew uninstall openssl freetds (모든 버전이 삭제될 때 까지 여러번 수행해야 할 수도 있음)
$ brew update
$ brew install openssl freetds

openssl 1.0.2j 와 freetds 1.00.15 가 설치되었습니다. 이제 pymssql 을 설치합니다. 

$ pip install pymssql

컴파일이 안됩니다. 

$ pip install pymssql
...
  _mssql.c:18814:15: error: use of undeclared identifier 'DBVERSION_80'
      __pyx_r = DBVERSION_80;
                ^
  1 error generated.
  error: command 'clang' failed with exit status 1

구글은 모든 것을 알고 있습니다. pymssql 2.2.0 dev 버전이 freetds 1.00 버전에 대해 에러 없이 컴파일 된다고 합니다. 깃헙에서 pymssql을 clone 하고 설치해봅니다.

$ git clone https://github.com/pymssql/pymssql.git
$ python setup.py install

이제 또 테스트해봅니다. connect - select 1 - close 계속 실행시켜봅니다. 3000번쯤 실행해도 에러가 나지 않습니다.

누가누가 범인인가?

php로 구동되는 서버들과 python 에서 에러가 떨어진다는 점에 착안하여 freetds 아니면 openssl 이 범인이라고 생각했습니다. 둘중에 어떤것인지 다시한번 알아보기 위해 각각 하위버전으로 설치하여 테스트해봤습니다.

openssl, freetds 를 직접 소스를 받아서 설치 설정하는것은 매우 귀찮은 일이므로 brew 를 활용해보기로 합니다. 역시 폭풍 검색을 한 후, brew 를 하드코어적으로 다뤄줘야 한다는 것을 깨닫습니다. 하지만 나도 하드코어니까 괜찮아.

$ brew uninstall openssl
$ cd /usr/local/Homebrew/Library/Taps/homebrew/homebrew-core/Formula
$ git log openssl.rb
( 커밋 로그에서 가장 조상인 openssl 버전을 찾아보니.. 1.0.2h_1... 조상은 민망하고 작은외삼촌 정도.. )
$ git checkout 12c398fc56ab0b2860957da2c61f3145c555ccbb openssl.rb
$ brew install openssl

그냥 여전히 잘되네요. freetds 를 다운그레이드해봅니다.

$ brew uninstall freetds
$ rm -rf /usr/local/lib/python2.7/site-packages/pymssql-2.*
 ( pymssql 을 소스로 설치해서 pip uninstall 로는 잘 제거되지 않습니다.
   시스템별로 egg 설치되는 경로는 다를 수 있습니다. )
$ brew install freetds091
$ pip install pymysql

네 문제가 발생하네요!! freetds 의 구버전 0.91 이 문제가 된다는 사실을 알 수 있습니다.

리눅스 서버들에 freetds 신버전 설치

이제 서비스 서버들에 freetds 설치를 해야하는 마지막 과정이 남았어요. 우아한 형제들이 사용하는 시스템들을 보니 두가지 입니다.

  • amazon linux
  • cent OS

두가지 모두 rpm 으로 시스템 패키지를 관리하는데, 둘다 freetds 1.00.15는 준비된 rpm 파일을 찾을 수 없었습니다. 어쩔 수 있나요? 직접 컴파일 해야 합니다. shared object ( .so 파일 ) 들이 설치된 경로를 찾아봅니다.

$ ldd $(which tsql)
...
/usr/lib64/libsybdb.so.5
/usr/lib64/libt.so.5
...

라이브러리들은 /usr/lib64 에 설치되어 있네요. 설정파일은 /etc/freetds.conf 파일입니다.

설치경로를 찾는 다른 방법은 rpm 명령을 이용하는겁니다.

# rpm -ql freetds

경로들을 알았으니 컴파일을 해봅시다.

$ wget ftp://ftp.freetds.org/pub/freetds/stable/freetds-1.00.15.tar.bz2
$ tar xf freetds-1.00.15.tar.bz2
$ cd freetds-1.00.15
$ ./configure –prefix=/usr –libdir=/usr/lib64 –sysconfdir=/etc
  ( /usr/lib64 경로는 시스템별로 다를 수 있으니 잘 찾아보고 결정하시면 됩니다. )
$ make -j $(nproc)
$ sudo make install-exec
  ( 이런 저런 파일들은 빼고 바이너리만 설치합니다. )

테스트를 해보니 php 코드에서 exception 이 발생합니다. sql server 의 datatime type을 php DateTime type 으로 받는 과정에서 발생하는 것으로 생각되는데, 에러로그를 남겨두지 않아 정확한 메시지를 쓸 수는 없지만 다음과 같은 내용이었습니다.

"Oct 19 2016 12:34:56"을 DateTime type 으로 변경할 수 없습니다.

아마도 최하위버전의 tds protocol 이 선택된 경우 날짜를 문자열로 전송하는 것으로 생각됩니다. tds version = 8.0 인 설정에서는 최하위 버전의 tds 프로토콜을 사용하는 것으로 보입니다.

이것은 /etc/freetds.conf 에서 tds version 을 변경하는 것으로 해결됩니다. sql server 버전 별 tds version

[global]
tds version = 7.4

php, python 을 사용하는 모든 서버에 freetds 를 설치한 후 모든 에러가 사라지고 서비스가 정상화되었습니다.

반성과 교훈

sql server 에서 access violation 에러가 발생하여 정기점검때 os/db patch 를 적용하는 것으로 정했으나 (급박하게) 미리 테스트해볼 생각을 하지 못했습니다. 서비스 DB 의 OS, DB engine 패치 작업은 Beta 환경에서 먼저 적용/테스트 한 후 수행하는게 실제 장애 상황을 방지하는 좋은 방법입니다.

이 글은 교차투고되었습니다. wordpress

참고

  • macos 에서 link 된 shared object 를 찾으려면? 
예) pymssql 모듈이 어느 freetds library 에 link 되었을까?
( pymssql.so 파일이 어디 있는지는 pip install 이나 setup.py install 실행시 출력됩니다. 혹은, python sys.path 에서 찾을 수 있습니다. )
$ otool -L pymssql.so
pymssql.so:
    /usr/local/opt/freetds/lib/libsybdb.5.dylib (compatibility version 7.0.0, current version 7.0.0)
    /usr/lib/libSystem.B.dylib (compatibility version 1.0.0, current version 1238.0.0)
$ ls -l /usr/local/opt/freetds
lrwxr-xr-x  1 nazgul33  admin  24 Oct 19 12:14 /usr/local/opt/freetds -> ../Cellar/freetds/1.00.15