From mboxrd@z Thu Jan 1 00:00:00 1970 From: LC Bruzenak Subject: Re: [RFC][PATCH] audit: log join and part events to the read-only multicast log socket Date: Thu, 23 Oct 2014 09:19:49 -0500 Message-ID: <54490E85.6020403@magitekltd.com> References: <30ef5c1ba42b52953e5684a0322975c3f0fadc77.1412706089.git.rgb@redhat.com> <2123008.Fh5Qt7eGrO@sifl> <54481D6C.9040809@magitekltd.com> <35356560.bDSLJB7XGk@sifl> Mime-Version: 1.0 Content-Type: multipart/mixed; boundary="===============0732960775818203263==" Return-path: Received: from mx1.redhat.com (ext-mx16.extmail.prod.ext.phx2.redhat.com [10.5.110.21]) by int-mx11.intmail.prod.int.phx2.redhat.com (8.14.4/8.14.4) with ESMTP id s9NEK3tP029782 for ; Thu, 23 Oct 2014 10:20:03 -0400 Received: from mail-ob0-f180.google.com (mail-ob0-f180.google.com [209.85.214.180]) by mx1.redhat.com (8.14.4/8.14.4) with ESMTP id s9NEJmZq026238 (version=TLSv1/SSLv3 cipher=RC4-SHA bits=128 verify=FAIL) for ; Thu, 23 Oct 2014 10:19:49 -0400 Received: by mail-ob0-f180.google.com with SMTP id vb8so798285obc.25 for ; Thu, 23 Oct 2014 07:19:48 -0700 (PDT) In-Reply-To: <35356560.bDSLJB7XGk@sifl> List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Sender: linux-audit-bounces@redhat.com Errors-To: linux-audit-bounces@redhat.com To: Paul Moore , linux-audit@redhat.com List-Id: linux-audit@redhat.com This is a cryptographically signed message in MIME format. --===============0732960775818203263== Content-Type: multipart/signed; protocol="application/pkcs7-signature"; micalg=sha1; boundary="------------ms030102080200060506020804" This is a cryptographically signed message in MIME format. --------------ms030102080200060506020804 Content-Type: text/plain; charset=windows-1252 Content-Transfer-Encoding: quoted-printable On 10/22/2014 04:29 PM, Paul Moore wrote: > Well, like I said, It's probably safer that way as the code will work=20 > regardless. Time to break bad habits :) > I hear you. But there's working and there's working well. As long as we don't suffer a search response degradation by changing the assumptive order, as I said, I'm OK with going back and reworking code. If it makes searching real data unusable, it's now broken some operational stuff. As it is, I already have to move the last 24 hours off to a different area and make searching go day-by-day only. Otherwise the logs are too bi= g. I chose a 100MB file size a while back as a sweet spot based on the observation that each file could be parsed in some time acceptable to security managers. Just some info on the amount of data I've seen in real world examples: On a normally-busy site, each day, we will generate ~1-4GB of events. It used to be much more, but our team has managed to keep it down. I'd say that often more time is spent reducing the events than analyzing them. If not, they grow to a size you simply cannot parse in people-time. I did have way more, but we've become better adept at spotting and preventing event storms. Here is a current test machine's audit log directory. I have to go look to see what went wrong, obviously something did, but this kind of thing can and does happen in the real world. Note the time stamps. 100MB every minute or two is moving right along. We push all audit data off to a collector machine so it doesn't dominate the disks or otherwise hog the business server resources. BTW - funny that I just happened to login to this machine to check its status. Whatever was running amok stopped soon after 00:57. This sometimes just happens. I've seen this go on for hours more in fielded systems. Almost always something is really wrong, but the system is supposed to maintain security and be usable through these times as well. [root@audit audit]# ls -alt total 4179016 -rw-------. 1 root root 84835735 Oct 23 02:49 audit.log drwxr-x---. 2 root root 4096 Oct 23 00:57 . -r--------. 1 root root 104857789 Oct 23 00:57 audit.log.1 -r--------. 1 root root 104857663 Oct 23 00:56 audit.log.2 -r--------. 1 root root 104857639 Oct 23 00:55 audit.log.3 -r--------. 1 root root 104857608 Oct 23 00:54 audit.log.4 -r--------. 1 root root 104857874 Oct 23 00:52 audit.log.5 -r--------. 1 root root 104857864 Oct 23 00:51 audit.log.6 -r--------. 1 root root 104857670 Oct 23 00:50 audit.log.7 -r--------. 1 root root 104857740 Oct 23 00:49 audit.log.8 -r--------. 1 root root 104857644 Oct 23 00:48 audit.log.9 -r--------. 1 root root 104857871 Oct 23 00:47 audit.log.10 -r--------. 1 root root 104857602 Oct 23 00:46 audit.log.11 -r--------. 1 root root 104857755 Oct 23 00:45 audit.log.12 -r--------. 1 root root 104857907 Oct 23 00:44 audit.log.13 -r--------. 1 root root 104857973 Oct 23 00:43 audit.log.14 -r--------. 1 root root 104857632 Oct 23 00:42 audit.log.15 -r--------. 1 root root 104857843 Oct 23 00:42 audit.log.16 -r--------. 1 root root 104857769 Oct 23 00:41 audit.log.17 -r--------. 1 root root 104857864 Oct 23 00:40 audit.log.18 -r--------. 1 root root 104857862 Oct 23 00:39 audit.log.19 -r--------. 1 root root 104857757 Oct 23 00:38 audit.log.20 -r--------. 1 root root 104857601 Oct 23 00:36 audit.log.21 -r--------. 1 root root 104857663 Oct 23 00:35 audit.log.22 -r--------. 1 root root 104857711 Oct 23 00:34 audit.log.23 -r--------. 1 root root 104857806 Oct 23 00:33 audit.log.24 -r--------. 1 root root 104857722 Oct 23 00:32 audit.log.25 -r--------. 1 root root 104857684 Oct 23 00:31 audit.log.26 -r--------. 1 root root 104857761 Oct 23 00:30 audit.log.27 -r--------. 1 root root 104857975 Oct 23 00:29 audit.log.28 -r--------. 1 root root 104857702 Oct 23 00:28 audit.log.29 -r--------. 1 root root 104857771 Oct 23 00:27 audit.log.30 -r--------. 1 root root 104857990 Oct 23 00:25 audit.log.31 -r--------. 1 root root 104857629 Oct 23 00:24 audit.log.32 -r--------. 1 root root 104857663 Oct 23 00:23 audit.log.33 -r--------. 1 root root 104857852 Oct 23 00:22 audit.log.34 -r--------. 1 root root 104857841 Oct 23 00:21 audit.log.35 -r--------. 1 root root 104857634 Oct 23 00:20 audit.log.36 -r--------. 1 root root 104857690 Oct 23 00:19 audit.log.37 -r--------. 1 root root 104857623 Oct 23 00:18 audit.log.38 -r--------. 1 root root 104857711 Oct 23 00:17 audit.log.39 -r--------. 1 root root 104857867 Oct 23 00:02 audit.log.40 I started an "aureport -i --summary". I realize my aureport and ausearch don't use the auparse library, but they will soon, if not already, in the newer code. I just wanted to give you a feel for data amounts in your considerations. Also I have designs for some new tools I want to deploy which definitely will use libauparse, if it's usable. At 4GB+ of audit data, this report isn't returning yet. The nice thing is it isn't leaking memory, or if it is, it isn't gushing (from "top"): 31485 root 20 0 217m 104m 89m R 99.7 0.4 22:29.91 aureport So I guess from a real user perspective I'm just worried that fixing an order dependency will have adverse effects on retrieval. So my vote would be to promote anything which makes searching/parsing faster. Or we need a different paradigm entirely. I've been doing some other stuff while writing this. The aureport isn't done after 37+ minutes: 31485 root 20 0 220m 96m 78m R 100.0 0.4 37:22.38 aureport I realize if I were sitting inside a google infrastructure this would be different, but I'm not. So when guys try to understand what happened during, in this case, the first hour of the day, the time it takes to return the answer can make them think it's broken. This is why to me, speed of parse/retrieval is important. The aureport is still cranking: 31485 root 20 0 221m 76m 57m R 100.0 0.3 44:21.15 aureport Now if a few queries happen at the same time, and they can, we start seeing some real work on this machine. It's a reasonable machine - dual quad core Xeon with 24GB of RAM - dedicated to storage and retrieval of system audit data (from "cat /proc/cpuinfo"): =2E.. processor : 7 vendor_id : GenuineIntel cpu family : 6 model : 44 model name : Intel(R) Xeon(R) CPU X5677 @ 3.47GHz stepping : 2 cpu MHz : 1600.000 cache size : 12288 KB So hopefully this gives you a sense of the way the audit data can stack up; to me every millisecond/event saved is potentially hours earned. Report is still running btw: 31485 root 20 0 222m 103m 83m R 99.9 0.4 56:18.64 aureport =46rom what I've read on the list, there are other users who have similar= loads. I'm not sure if this makes any real difference in your thought process or not, and you probably knew most of this anyway. Just wanted to throw out some data points for consideration in case they matter. I waited until this morning to send this so I could see how long the aureport took. [root@audit audit]# time aureport -i --summary Summary Report =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D Range of time in logs: 10/23/2014 00:01:02.305 - 10/23/2014 09:58:40.745 Selected time for report: 10/23/2014 00:01:02 - 10/23/2014 09:58:40.745 Number of changes in configuration: 2892 Number of changes to accounts, groups, or roles: 0 Number of logins: 47 Number of failed logins: 2 Number of authentications: 2712 Number of failed authentications: 355 Number of users: 8 Number of terminals: 41 Number of host names: 7 Number of executables: 112 Number of files: 536772 Number of AVC's: 5791 Number of MAC events: 3045 Number of failed syscalls: 2502700 Number of anomaly events: 525 Number of responses to anomaly events: 0 Number of crypto events: 14 Number of keys: 36 Number of process IDs: 30494 Number of events: 8526658 real 428m11.405s user 427m21.833s sys 0m4.014s Thank you! LCB --=20 LC (Lenny) Bruzenak lenny@magitekltd.com --------------ms030102080200060506020804 Content-Type: application/pkcs7-signature; name="smime.p7s" Content-Transfer-Encoding: base64 Content-Disposition: attachment; filename="smime.p7s" Content-Description: S/MIME Cryptographic Signature MIAGCSqGSIb3DQEHAqCAMIACAQExCzAJBgUrDgMCGgUAMIAGCSqGSIb3DQEHAQAAoIIEZDCC BGAwggNIoAMCAQICEwZQV0xKmXg6VpNOYV4AVY8RbPYwDQYJKoZIhvcNAQEFBQAwgYIxCzAJ BgNVBAYTAlVTMR4wHAYDVQQLExV3d3cueHJhbXBzZWN1cml0eS5jb20xJDAiBgNVBAoTG1hS YW1wIFNlY3VyaXR5IFNlcnZpY2VzIEluYzEtMCsGA1UEAxMkWFJhbXAgR2xvYmFsIENlcnRp ZmljYXRpb24gQXV0aG9yaXR5MB4XDTE0MDgxNDA5NTMyMFoXDTE1MDgxNDE1NTMyMFowcTEd MBsGA1UEAwwUbGVubnlAbWFnaXRla2x0ZC5jb20xDjAMBgNVBAoMBXNtaW1lMQ4wDAYDVQQI DAVzbWltZTELMAkGA1UEBhMCVVMxIzAhBgkqhkiG9w0BCQEWFGxlbm55QG1hZ2l0ZWtsdGQu Y29tMIIBIjANBgkqhkiG9w0BAQEFAAOCAQ8AMIIBCgKCAQEAyk/YzpnShgUImRJTL/rtYoP4 rP3rR9A45kty5KcQ+xaq7B2M/irmosxQ96hg1LcJrh9LEG9gmAjiQK32QT9hAND47Frag3+6 4txUSuiW4Wh1Q96avqg30hC0oZvylAyaqx1DRGw1jv3UVMyBOMWG7boxWOOPqIvBK6NaQGDD j74tfb+MyjRGLpUq6IUzVhMiHX1pRXSlprS0jH0rSQQrGZIGnqRT2+LlhbU6jYcBLS7dsS38 gHaKhs5hgSsFIT0hmHvF7EqKLIpeqA4sRCdtHUrjCjRXTo4G0SYcPSHJegR9UADWWsyXaK2l VMQG/yvczd/EcrJFaeTZTxQGzBInmwIDAQABo4HeMIHbMAsGA1UdDwQEAwIFoDATBgNVHSUE DDAKBggrBgEFBQcDBDAdBgNVHQ4EFgQUbdNQFOkqZZpvYP3Og5yjTF5MKi4wHwYDVR0jBBgw FoAUxk+iPQZjhAmczmLkBKyNXLXpthswQwYDVR0gBDwwOjA4BgpghkgBhv1kAgIBMCowKAYI KwYBBQUHAgEWHGh0dHBzOi8vc3NsLnRydXN0d2F2ZS5jb20vQ0EwMgYDVR0fBCswKTAnoCWg I4YhaHR0cDovL2NybC50cnVzdHdhdmUuY29tL1hHQ0EuY3JsMA0GCSqGSIb3DQEBBQUAA4IB AQA4p5zP1UtMZrLRslU6wXrprLWT3Rw4yeYYnayveaKb/MN9iKI95gQeAlObmSk00GU3EngH Y3EscFOYfQY9rkZCqSFSx+gc04FFBxFDrjs28McrD6MIcuFcRYLxri0QXMZ5yrkCw1sHwZHp 6R0/CvVcz7RvHREM108BAs/0SccZoTh2z9Py6IZcr+Ye3KsYpyET3Zu8Lw2VV7z24DntjMN6 3GC3pnbrLxadzxdAk5AkWo23FsNQElSJaG9PqoKV8blk1XI8dVQAtD7YBGI40sCW7VaYPZ0G tYdyGROQWMAN6gj1pUt9oeIlLbaobvq8u5Gahhc+cwMWNycKSyOQWf8eMYID7zCCA+sCAQEw gZowgYIxCzAJBgNVBAYTAlVTMR4wHAYDVQQLExV3d3cueHJhbXBzZWN1cml0eS5jb20xJDAi BgNVBAoTG1hSYW1wIFNlY3VyaXR5IFNlcnZpY2VzIEluYzEtMCsGA1UEAxMkWFJhbXAgR2xv YmFsIENlcnRpZmljYXRpb24gQXV0aG9yaXR5AhMGUFdMSpl4OlaTTmFeAFWPEWz2MAkGBSsO AwIaBQCgggIpMBgGCSqGSIb3DQEJAzELBgkqhkiG9w0BBwEwHAYJKoZIhvcNAQkFMQ8XDTE0 MTAyMzE0MTk0OVowIwYJKoZIhvcNAQkEMRYEFLH1hCRo9QuM97PNcpBbTcmE1pq/MGwGCSqG SIb3DQEJDzFfMF0wCwYJYIZIAWUDBAEqMAsGCWCGSAFlAwQBAjAKBggqhkiG9w0DBzAOBggq hkiG9w0DAgICAIAwDQYIKoZIhvcNAwICAUAwBwYFKw4DAgcwDQYIKoZIhvcNAwICASgwgasG CSsGAQQBgjcQBDGBnTCBmjCBgjELMAkGA1UEBhMCVVMxHjAcBgNVBAsTFXd3dy54cmFtcHNl Y3VyaXR5LmNvbTEkMCIGA1UEChMbWFJhbXAgU2VjdXJpdHkgU2VydmljZXMgSW5jMS0wKwYD VQQDEyRYUmFtcCBHbG9iYWwgQ2VydGlmaWNhdGlvbiBBdXRob3JpdHkCEwZQV0xKmXg6VpNO YV4AVY8RbPYwga0GCyqGSIb3DQEJEAILMYGdoIGaMIGCMQswCQYDVQQGEwJVUzEeMBwGA1UE CxMVd3d3LnhyYW1wc2VjdXJpdHkuY29tMSQwIgYDVQQKExtYUmFtcCBTZWN1cml0eSBTZXJ2 aWNlcyBJbmMxLTArBgNVBAMTJFhSYW1wIEdsb2JhbCBDZXJ0aWZpY2F0aW9uIEF1dGhvcml0 eQITBlBXTEqZeDpWk05hXgBVjxFs9jANBgkqhkiG9w0BAQEFAASCAQCDBZCJb66KxOTJLQDq XOiVVfJU+hfp6yNBhj9Xv9rOYRpV8rOkbk1mPKJzHuz8JfFOA4Z0Bzg+QVZM/QR9tesVrxEl AyaKvKqpuJuAlAZqHgQAHDABhOLOEM8hXBzYwBl5dMLLTd2Mhp5+MI7eelEaDgewG8cH0Oba qcMnyBb/xaElOxf7zyVb72+8637+ks4RP0umUKQ+FbW2OM2rCyhkJqb3GrkjoTSatCFnOsEG up5pTxC5JFajLJUYRTnItLalEa4GGjcegr8yoKwXLRLuCbbTyO91ovQEaAno93bVhEmgw4WM t4PYt023a1e+kF87ZxRGPkimwyrelb5/NJAmAAAAAAAA --------------ms030102080200060506020804-- --===============0732960775818203263== Content-Type: text/plain; charset="us-ascii" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit Content-Disposition: inline --===============0732960775818203263==--