로그를 볼 때 유용한 shell 명령어들

서버 개발을 하다보면, 로그를 밥먹듯이 보게 된다. 로그는 디버깅을 하는데 이용되기도 하지만, 때로는 원하는 통계와 데이터를 얻기 위해 사용되기도 한다.
이 글은 후자의 경우, 내가 자주 겪었던 문제와 이를 해결하기 위해 사용했던 방법들을 정리하기 위해 작성하였다.

예제에 사용된 access_log는, 운영하고 있는 블로그의 실제 access.log 파일을 사용하였습니다.

특정 문자열이 포함된 줄 뽑아내기

Mac OS를 사용하고 있는 유저의 요청 로그만을 뽑고 싶다고 가정해보자.
Mac OS를 사용하고 있는 유저의 로그에는 'Macintosh; Intel Mac OS X' 이라는 문자열이 존재한다는 공통점을 이용하면, grep 으로 쉽게 뽑아낼 수 있다.

$ grep 'Macintosh; Intel Mac OS X' access.log

만약 총 몇 개의 요청이 있었는지 카운트하고 싶다면, wc -l 명령어를 파이프라인으로 연결하면 된다.

$ grep 'Macintosh; Intel Mac OS X' access.log | wc -l

32  

특정 위치의 문자열 뽑아내기

이번에는 로그에서 GET 으로 들어온 요청의 경로(PATH)만을 뽑아내고 싶다고 가정해보자.
일단 GET 으로 들어온 요청은 앞에서와 동일하게 grep 만으로 쉽게 뽑아낼 수 있다.

$ grep 'GET /' access.log

문제는 경로를 뽑아내는 것인데, 로그를 자세히 보면 각 줄을 공백으로 구분했을 때 7번째 구성요소가 항상 경로인 점을 발견할 수 있다. 이러한 규칙을 이용하면 cut 명령어로 뽑아낼 수 있다.

$ grep 'GET /' access.log | cut -d " " -f 7

/
/2019/07/15/java-heap-dump-analysis/
/robots.txt
...

만약 각 경로별로 카운트를 하고 싶다면, sortuniq 명령어를 함께 이용하면 된다.

$ grep 'GET /' access.log | cut -d " " -f 7 | sort | uniq -c

73 /  
 3 /2016/09/25/decorator-class/
 1 /2016/09/25/decorator-function/
 1 /2016/10/05/ci-github-slack
 1 /2016/10/05/ci-github-slack/
...

추가로, 가장 많이 카운트된 순서대로 위에서부터 출력하고 싶다면, sort 를 한번 더 사용하면 된다.

$ grep 'GET /' access.log | cut -d " " -f 7 | sort | uniq -c | sort -nr

73 /  
40 /assets/js/jquery.fitvids.js?v=6ea3fea03b  
40 /assets/js/index.js?v=6ea3fea03b  
39 /assets/css/screen.css?v=6ea3fea03b  
35 /favicon.ico  
...

특정 패턴에 해당하는 문자열 뽑아내기

이번에는 GET /favicon.ico 으로 들어온 요청에서 HH(시):MM(분):SS(초) +0000 부분만을 깔끔하게 뽑아내고 싶다고 가정해보자.
일단 앞서 배운 것들을 이용해 [05/Nov/2019:HH:MM:SS +0000] 라고 적힌 부분만을 뽑아낼 수 있다.

$ grep 'GET /favicon.ico' access.log | cut -d " " -f 4 -f 5

[05/Nov/2019:19:33:45 +0000]
[05/Nov/2019:19:34:40 +0000]
[05/Nov/2019:20:00:47 +0000]
...

먼저 앞의 [05/Nov/2019: 부분을 제거해보자. 이때 awk 명령어를 이용하면 이러한 처리를 쉽게 할 수 있다.

$ grep 'GET /favicon.ico' access.log | cut -d " " -f 4 -f 5 | awk -F '0[5-6]/Nov/2019:' '{print $2}'

19:33:45 +0000]  
19:34:40 +0000]  
20:00:47 +0000]  
...

유사한 방법으로 끝에 붙어있는 ] 도 제거할 수 있다.

$ grep 'GET /favicon.ico' access.log | cut -d " " -f 4 -f 5 | awk -F '0[5-6]/Nov/2019:' '{print $2}' | awk -F ']' '{print $1}'

19:33:45 +0000  
19:34:40 +0000  
20:00:47 +0000  
...

또는 정규표현식과 awk의 내장함수 match(), substr() 함수를 이용하면 정규표현식에 해당하는 문자열만을 쉽게 뽑아낼 수 있다.

$ grep 'GET /favicon.ico' access.log | awk 'match($0, "[[:digit:]]{2}:[[:digit:]]{2}:[[:digit:]]{2} \\+0000")  {print substr($0, RSTART, RLENGTH)}'

19:33:45 +0000  
19:34:40 +0000  
20:00:47 +0000  

특정 위치의 문자열 기준으로 정렬하기

이번에는 로그에서 GET 으로 들어온 요청의 경로(PATH)의 오름차순으로 로그를 정렬해보자.
앞에서 배운 것을 활용하면 특정 위치의 문자열을 뽑은 후, 그 문자열들을 정렬한 결과를 쉽게 출력해볼 수 있다.

$ grep 'GET /' access.log | cut -d " " -f 7 | sort

/
/
...
/tag/ruby-on-rails/
/tag/study/
/tag/study/

하지만 내가 정말 원하는 것은 뽑아낸 PATH만이 아닌, PATH를 기준으로 정렬된 전체 로그를 출력하고 싶다.
이러한 경우를 위해 sort 는 특정 위치의 문자열에 대해 정렬할 수 있는 옵션을 제공해주고 있다. 각 줄을 공백으로 구분했을 때 7번째 구성요소를 기준으로 오름차순 정렬하고 싶은 것이므로, 아래와 같이 sort 명령어 옵션 -t-k에 적절한 값을 넣으면 된다.

$ grep 'GET /' access.log | sort -t " " -k 7

67.212.187.106 - - [05/Nov/2019:19:31:24 +0000] "GET / HTTP/1.0" 200 14299 "-" "-"  
5.189.142.121 - - [05/Nov/2019:19:57:24 +0000] "GET / HTTP/1.0" 301 184 "-" "masscan/1.0 (https://github.com/robertdavidgraham/masscan)"  
138.197.64.71 - - [05/Nov/2019:21:25:51 +0000] "GET / HTTP/1.1" 200 14299 "-" "-"  
...
46.229.168.161 - - [05/Nov/2019:20:57:10 +0000] "GET /tag/study/ HTTP/1.1" 200 3144 "-" "Mozilla/5.0 (compatible; SemrushBot/6~bl; +http://www.semrush.com/bot.html)"  
138.197.64.71 - - [05/Nov/2019:21:26:14 +0000] "GET /tag/study/ HTTP/1.1" 200 3144 "https://jupiny.com" "Mozilla/5.0 (X11; Datanyze; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/65.0.3325.181 Safari/537.36"  

만약 7번째 문자열이 동일한 경우는 그 다음 8번째의 문자열을 기준으로 정렬되고, 또 동일하다면 그 다음 9번째, 10번째,... 이러한 순서로 정렬이 됨을 볼 수 있다.


특정 패턴에 해당하는 문자열 기준으로 정렬하기

이번에는 더 난이도를 높여서 특정 위치의 문자열이 아닌, 특정 패턴에 해당하는 문자열을 뽑아서 그 문자열을 기준으로 전체 로그를 정렬해보자.

만약 GET /yyyy/mm/dd/[URL 이름]/ 으로 들어온 요청 중에서, URL 이름 의 오름차순으로 전체 로그를 정렬하고 싶다고 하자.
먼저 해당 패턴에 해당하는 문자열(여기선 URL 이름)을 뽑아내야 한다. 앞에서와 마찬가지로 awk 명령어와 awk의 내장함수 match(), substr() 함수를 이용하여 정규표현식에 해당하는 문자열을 뽑아내보자.

$ awk 'match($0, "GET /[[:digit:]]{4}/[[:digit:]]{2}/[[:digit:]]{2}/[a-z0-9\-]+/")  {print substr($0, RSTART+16, RLENGTH-17)}' access.log

java-heap-dump-analysis  
test-in-multiple-environments-using-pyenv-and-tox  
linux-command-1-grep-less-head-tail  
sort-korean-in-postgresql  
ci-github-slack  
...

뒤에 sort를 파이프라인으로 연결하면 해당 문자열들은 오름차순으로 정렬되겠지만, 아까와 마찬가지로 이는 우리가 원하는 결과가 아니다. 우리가 원하는 것은 이 문자열을 기준으로 정렬된 전체 로그이다.

이를 해결하기 위해 약간의 꼼수(?)를 써보자. ('꼼수'라고 언급한 이유는 사실 썩 마음에 드는 깔끔한 해결법이 아니었기 때문인데, 혹시라도 더 좋은 방법을 찾게 된다면 글을 업데이트하도록 하겠다.)
이 해결 방법에는 크게 3단계가 필요하다.

  1. 정규표현식으로 뽑아낸 문자열\t원본 형태로 출력
  2. 출력된 결과를 정렬 -> 정규표현식으로 뽑아낸 문자열 기준으로 정렬됨
  3. \t 뒤의 원본만을 출력

한 단계식 순서대로 적용해보자.
먼저 1단계, 정규표현식으로 뽑아낸 문자열\t원본 형태로 출력해보자.

$ awk 'match($0, "GET /[[:digit:]]{4}/[[:digit:]]{2}/[[:digit:]]{2}/[a-z0-9\-]+/")  {print substr($0, RSTART+16, RLENGTH-17)"\t"$0}' access.log

java-heap-dump-analysis 66.249.75.38 - - [05/Nov/2019:19:20:35 +0000] "GET /2019/07/15/java-heap-dump-analysis/ HTTP/1.1" 200 5556 "-" "Mozilla/5.0 (compatible; Googlebot/2.1; +http://www.google.com/bot.html)"  
test-in-multiple-environments-using-pyenv-and-tox       46.229.168.140 - - [05/Nov/2019:19:29:37 +0000] "GET /2018/07/31/test-in-multiple-environments-using-pyenv-and-tox/ HTTP/1.1" 200 6013 "-" "Mozilla/5.0 (compatible; SemrushBot/6~bl;  
+http://www.semrush.com/bot.html)"
linux-command-1-grep-less-head-tail     23.100.232.233 - - [05/Nov/2019:19:37:54 +0000] "GET /2017/07/09/linux-command-1-grep-less-head-tail/ HTTP/1.1" 200 4655 "-" "Mozilla/5.0 (compatible; MSIE 9.0; Windows NT 6.0; Trident/5.0;  Trident  
/5.0)"
...

이제 이 로그들을 sort를 이용해 오름차순으로 정렬해보자.

$ awk 'match($0, "GET /[[:digit:]]{4}/[[:digit:]]{2}/[[:digit:]]{2}/[a-z0-9\-]+/")  {print substr($0, RSTART+16, RLENGTH-17)"\t"$0}' access.log | sort

caching-using-redis-on-django   221.133.55.100 - - [06/Nov/2019:00:22:42 +0000] "GET /2018/02/27/caching-using-redis-on-django/ HTTP/1.1" 200 7060 "https://www.google.com/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/78.0.3904.87 Safari/537.36"  
caching-using-redis-on-django   221.133.55.100 - - [06/Nov/2019:00:44:22 +0000] "GET /2018/02/27/caching-using-redis-on-django/ HTTP/1.1" 304 0 "https://www.google.com/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/78.0.3904.87 Safari/537.36"  
...
test-in-multiple-environments-using-pyenv-and-tox       46.229.168.140 - - [05/Nov/2019:19:29:37 +0000] "GET /2018/07/31/test-in-multiple-environments-using-pyenv-and-tox/ HTTP/1.1" 200 6013 "-" "Mozilla/5.0 (compatible; SemrushBot/6~bl; +http://www.semrush.com/bot.html)"  
test-in-multiple-environments-using-pyenv-and-tox       66.249.75.42 - - [06/Nov/2019:00:50:03 +0000] "GET /2018/07/31/test-in-multiple-environments-using-pyenv-and-tox/amp/ HTTP/1.1" 200 7486 "-" "Mozilla/5.0 (Linux; Android 6.0.1; Nexus 5X Build/MMB29P) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/41.0.2272.96 Mobile Safari/537.36 (compatible; Googlebot/2.1; +http://www.google.com/bot.html)"  

마지막으로, 정렬을 위해 임시로 앞에 붙였던 정규표현식으로 뽑아낸 문자열 부분을 cut 을 이용해 제거하면 된다.

$ awk 'match($0, "GET /[[:digit:]]{4}/[[:digit:]]{2}/[[:digit:]]{2}/[a-z0-9\-]+/")  {print substr($0, RSTART+16, RLENGTH-17)"\t"$0}' access.log | sort | cut -d $'\t' -f 2

221.133.55.100 - - [06/Nov/2019:00:22:42 +0000] "GET /2018/02/27/caching-using-redis-on-django/ HTTP/1.1" 200 7060 "https://www.google.com/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/78.0.3904.87 Safari/537.36"  
221.133.55.100 - - [06/Nov/2019:00:44:22 +0000] "GET /2018/02/27/caching-using-redis-on-django/ HTTP/1.1" 304 0 "https://www.google.com/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/78.0.3904.87 Safari/537.36"  
...
46.229.168.140 - - [05/Nov/2019:19:29:37 +0000] "GET /2018/07/31/test-in-multiple-environments-using-pyenv-and-tox/ HTTP/1.1" 200 6013 "-" "Mozilla/5.0 (compatible; SemrushBot/6~bl; +http://www.semrush.com/bot.html)"  
66.249.75.42 - - [06/Nov/2019:00:50:03 +0000] "GET /2018/07/31/test-in-multiple-environments-using-pyenv-and-tox/amp/ HTTP/1.1" 200 7486 "-" "Mozilla/5.0 (Linux; Android 6.0.1; Nexus 5X Build/MMB29P) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/41.0.2272.96 Mobile Safari/537.36 (compatible; Googlebot/2.1; +http://www.google.com/bot.html)"  

참고