چرا گنو لینوکس رو دوست دارم: پاسخ دادن به اینکه آیا سیستم ما وضعیت عادی داره یا مورد حمله است

ما سروری داریم که تازه تحویلش دادیم ولی هر روز حوالی ظهر با مشکل مواجه می شه. کار اصلی رو پروسه ای انجام می ده که اینجا بهش می گیم A. چندین پروسه A می تونن همزمان بالا باشن و کار کنن و ما گفتیم حداکثر این تعداد باید ۱۰۰ باشه. یعنی در صورت زیاد شدن بار، ۱۰۰ تا A بالا می یان و تقریبا صد برابر بهتر از یک A کار می کنن. یک بررسی سریع نشون می ده که در لحظه بروز مشکل دقیقا ۱۰۰ تا از پروسه A فعاله:

# ps -ef | grep A | wc -l
101

مشخصه دیگه: ps -ef پروسه ها رو نشون می ده، grep A فقط خط هایی که توشون A هست رو جدا می کنه و در نهایت wc -l تعداد خط ها رو می شمره (اگر گفتین چرا به جای ۱۰۰ تا شده صد و یکی؟).

علی الحساب تعداد Aها رو به حداکثر ۱۰۰۰ عدد افزایش می دیم و می ریم سراغ سوالی که مطرحه:

آیا ما مورد حمله هستیم؟ آیا حوالی ظهر سیستمی شروع به کار با سیستم ما می کنه که فشار رو به شکل غیرعادی بالا می بره؟ یا واقعا این شرایط عادی است و اینقدر از این سیستم استفاده می شه؟

ما لاگ هایی به این شکل داریم که حاصل کار A هستن:

127.0.0.1 -  26/Jul/2015:03:48:53 +0430 "POST /index.php?_url=xxxxx" 200 /home/adp/www/xxx/public/index.php 357.489 2048 86.72%
127.0.0.1 -  26/Jul/2015:03:48:58 +0430 "POST /index.php?_url=qqqq" 200 /home/adp/www/xxx/public/index.php 91.281 1280 98.60%
127.0.0.1 -  26/Jul/2015:03:49:32 +0430 "GET /index.php?aaa" 200 /home/adp/www/xxx/public/index.php 373.649 1792 56.20%
127.0.0.1 -  26/Jul/2015:03:50:03 +0430 "HEAD /index.php" 200 /home/adp/www/xxx/public/index.php 43.501 1280 91.95%
127.0.0.1 -  26/Jul/2015:03:55:03 +0430 "HEAD /index.php" 200 /home/adp/www/xxxx/public/index.php 63.519 1280 94.46%

من از چند روز پیش این لاگ ها رو فعال کردم تا همه درخواست ها ذخیره بشن و حالا کافیه بشمرم ببینم چه خبره! اول بذارین همه لاگ هار و به همدیگه بچسبونیم:

jadi@funlife:/tmp/dir$ ls -ltrh 
total 36M
-rw------- 1 jadi jadi 9.2M Jul 22 03:17 www.access.log-20150722
-rw------- 1 jadi jadi 6.0M Jul 23 03:10 www.access.log-20150723
-rw------- 1 jadi jadi 6.4M Jul 24 03:25 www.access.log-20150724
-rw------- 1 jadi jadi 2.5M Jul 25 03:25 www.access.log-20150725
-rw------- 1 jadi jadi 7.4M Jul 26 03:45 www.access.log-20150726
-rw------- 1 jadi jadi 4.2M Jul 26 15:17 www.access.log
jadi@funlife:/tmp/dir$ cat www.access.log-* www.access.log > all.log
jadi@funlife:/tmp/dir$ ls -ltrh 
total 72M
-rw------- 1 jadi jadi 9.2M Jul 22 03:17 www.access.log-20150722
-rw------- 1 jadi jadi 6.0M Jul 23 03:10 www.access.log-20150723
-rw------- 1 jadi jadi 6.4M Jul 24 03:25 www.access.log-20150724
-rw------- 1 jadi jadi 2.5M Jul 25 03:25 www.access.log-20150725
-rw------- 1 jadi jadi 7.4M Jul 26 03:45 www.access.log-20150726
-rw------- 1 jadi jadi 4.2M Jul 26 15:17 www.access.log
-rw-rw-r-- 1 jadi jadi  36M Jul 26 15:30 all.log

راحت و سر راست. دستور cat که محتوای فایل ها رو نشون می ده، کل فایل ها رو چسبونده به هم تا یک فایل بزرگ به اسم all.log داشته باشیم که هر خطش چنین فرمی داره:

127.0.0.1 -  26/Jul/2015:03:48:53 +0430 "POST /index.php?_url=xxxxx" 200 /home/adp/www/xxx/public/index.php 357.489 2048 86.72%

کافه من تاریخ رو جدا کنم. دستور کات همیشه دوست منه:

jadi@funlife:/tmp/dir$ cut -d' ' -f4 all.log | head
20/Jul/2015:12:03:35
20/Jul/2015:12:03:36
20/Jul/2015:12:03:39
20/Jul/2015:12:03:39

جذاب نیست؟ به سادگی گفتم کات کن با جدا کننده اسپیس و فیلد چهارم رو به من بده ولی حالا فقط چند خط اول رو نشون بده (head). عملا کار تموم شده! کافیه این خطها رو بشمرم؛ البته بعد از حذف کردن ثانیه و دقیقه. برای حذف اینها کافیه شش کاراکتر آخر هر خط رو بردارم یا با همون دستور کات دوباره بگم بر اساس :‌ جدا کنه و فیلد اول و دوم رو به من بده. این راه دوم برای من سر راست تره:

jadi@funlife:/tmp/dir$ cut -d' ' -f4 all.log | cut -d: -f1,2 | head
20/Jul/2015:12
20/Jul/2015:12
20/Jul/2015:12
20/Jul/2015:12
20/Jul/2015:12
20/Jul/2015:12
20/Jul/2015:12
20/Jul/2015:12
20/Jul/2015:12
20/Jul/2015:12

چقدر عالی. دیگه فقط کافیه سورت کنیم و بگیم بشمره. دستور uniq‌ می تونه با سوییچ های مختلف کارهای مختلف کنه. مثلا فقط خط های غیرتکراری بده، فقط خط های تکراری رو بده، از هر خط بیشتر از یکبار نده، بشمره از هر خط چند تا هست و … و البته این دستور وابسته به اینه که ورودی اش مرتب شده باشه. پس:

jadi@funlife:/tmp/dir$ cut -d' ' -f4 all.log | cut -d: -f1,2 | sort -n | uniq -c > data
jadi@funlife:/tmp/dir$ head data
   2795 20/Jul/2015:12
   2363 20/Jul/2015:13
   2383 20/Jul/2015:14
   2251 20/Jul/2015:15
   1796 20/Jul/2015:16
   1599 20/Jul/2015:17
    843 20/Jul/2015:18
    704 20/Jul/2015:20
    765 20/Jul/2015:19
   1039 20/Jul/2015:21

چه کردیم! (: فقط کافیه ترسیمش کنیم:

و هر کسی که آمار یا حداقل نمودارهای نرمال بدونه می تونه بگه اتفاق غیرعادی ای در جریان نیست – حداقل در سطح درخواست ها. از ساعت هشت درخواست ها بالا می رن و بعد به شکلی نسبتا طبیعی افزایش پیدا می کنن تا آخر وقت اداری که دوباره آروم آروم پایین بیان. این پترن برای سایتی که مردم باهاش کار می کنن طبیعی است. مطمئنا می شه برنامه ما رو بهتر کرد ولی هدف من به عنوان مدیر سیستم این هست و بود که نشون بدم اتفاقی غیر عادی (درخواست ناگهانی از یک سیستم سر یک ساعت مشخص، حمله هکرها و …) در جریان نیست که تقریبا ثابت شده. اگر نمودارهای این تیپی دوست دارین بگین که بازم نمودارهایی واقعی از کارهای واقعی یک مدیر سیستم رو با هم مرور کنیم.