[Oisf-devel] File MD5 inconsistent checksums.
Nikolay Denev
ndenev at gmail.com
Thu Jul 12 08:55:34 UTC 2012
On Jul 12, 2012, at 11:44 AM, Victor Julien wrote:
> On 07/12/2012 10:42 AM, Nikolay Denev wrote:
>>
>> On Jul 12, 2012, at 11:11 AM, Victor Julien wrote:
>>
>>> On 07/12/2012 10:09 AM, Nikolay Denev wrote:
>>>>
>>>> On Jul 12, 2012, at 10:16 AM, Victor Julien wrote:
>>>>
>>>>> On 07/12/2012 08:27 AM, Nikolay Denev wrote:
>>>>>>
>>>>>> On Jul 12, 2012, at 9:25 AM, Nikolay Denev wrote:
>>>>>>
>>>>>>> On Jul 12, 2012, at 9:03 AM, Nikolay Denev wrote:
>>>>>>>
>>>>>>>> Hi,
>>>>>>>>
>>>>>>>> I'm seeing some strange behaviour while testing the filemd5 and md5 checksumming in general.
>>>>>>>>
>>>>>>>> I have a server which serves a file over http and the server port on the switch is mirrored to a box running suricata.
>>>>>>>>
>>>>>>>> I have the md5 of the file as it is on the server : c2ddef96c8a1aeddf316ff3cba37f318
>>>>>>>> When I do a curl download and pipe it to md5 the checksum matches.
>>>>>>>>
>>>>>>>> :~ ndenev$ curl http://testserver.example.com/test.img | md5
>>>>>>>> % Total % Received % Xferd Average Speed Time Time Time Current
>>>>>>>> Dload Upload Total Spent Left Speed
>>>>>>>> 100 117k 100 117k 0 0 1744k 0 --:--:-- --:--:-- --:--:-- 1933k
>>>>>>>> c2ddef96c8a1aeddf316ff3cba37f318
>>>>>>>>
>>>>>>>> However the filemd5 rule I've created never matches, and files-json.log shows completely different checksums, which also are not consistent?
>>>>>>>> And the filesize too differs, and as I said the curl on the client machine gives the same md5 each time.
>>>>>>>>
>>>>>>>> { "timestamp": "07\/12\/2012-07:56:15.944637", "ipver": 4, "srcip": "10.128.2.35", "dstip": "10.46.16.9", "protocol": 6, "sp": 80, "dp": 51135, "http_uri": "\/test.img", "http_host": "testserver.example.com", "http_referer": "<unknown>", "filename": "\/test.img", "magic": "ASCII text", "state": "CLOSED", "md5": "7890dc88c2f0f4d0706eef8bbfc33d75", "stored": false, "size": 4152 }
>>>>>>>> { "timestamp": "07\/12\/2012-07:56:25.033265", "ipver": 4, "srcip": "10.128.2.35", "dstip": "10.46.16.9", "protocol": 6, "sp": 80, "dp": 51136, "http_uri": "\/test.img", "http_host": "testserver.example.com", "http_referer": "<unknown>", "filename": "\/test.img", "magic": "ASCII text", "state": "CLOSED", "md5": "4b9fda98fbee8f4afea75b7b466b2e1a", "stored": false, "size": 3839 }
>>>>>>>> { "timestamp": "07\/12\/2012-07:56:30.232624", "ipver": 4, "srcip": "10.128.2.35", "dstip": "10.46.16.9", "protocol": 6, "sp": 80, "dp": 51138, "http_uri": "\/test.img", "http_host": "testserver.example.com", "http_referer": "<unknown>", "filename": "\/test.img", "magic": "ASCII text", "state": "CLOSED", "md5": "7890dc88c2f0f4d0706eef8bbfc33d75", "stored": false, "size": 4152 }
>>>>>>>> { "timestamp": "07\/12\/2012-07:56:35.410789", "ipver": 4, "srcip": "10.128.2.35", "dstip": "10.46.16.9", "protocol": 6, "sp": 80, "dp": 51140, "http_uri": "\/test.img", "http_host": "testserver.example.com", "http_referer": "<unknown>", "filename": "\/test.img", "magic": "ASCII text", "state": "CLOSED", "md5": "7890dc88c2f0f4d0706eef8bbfc33d75", "stored": false, "size": 4152 }
>>>>>>>> { "timestamp": "07\/12\/2012-07:56:39.225699", "ipver": 4, "srcip": "10.128.2.35", "dstip": "10.46.16.9", "protocol": 6, "sp": 80, "dp": 51142, "http_uri": "\/test.img", "http_host": "testserver.example.com", "http_referer": "<unknown>", "filename": "\/test.img", "magic": "ASCII text", "state": "CLOSED", "md5": "7890dc88c2f0f4d0706eef8bbfc33d75", "stored": false, "size": 4152 }
>>>>>>>>
>>>>>>>>
>>>>>>>> This is the latest entry in my stats.log :
>>>>>>>>
>>>>>>>> -------------------------------------------------------------------
>>>>>>>> Date: 7/12/2012 -- 08:00:24 (uptime: 0d, 00h 11m 20s)
>>>>>>>> -------------------------------------------------------------------
>>>>>>>> Counter | TM Name | Value
>>>>>>>> -------------------------------------------------------------------
>>>>>>>> tcp.sessions | Detect | 11097
>>>>>>>> tcp.ssn_memcap_drop | Detect | 0
>>>>>>>> tcp.pseudo | Detect | 6762
>>>>>>>> tcp.invalid_checksum | Detect | 22
>>>>>>>> tcp.no_flow | Detect | 0
>>>>>>>> tcp.reused_ssn | Detect | 0
>>>>>>>> tcp.memuse | Detect | 72351744
>>>>>>>> tcp.syn | Detect | 11520
>>>>>>>> tcp.synack | Detect | 10973
>>>>>>>> tcp.rst | Detect | 7998
>>>>>>>> tcp.segment_memcap_drop | Detect | 0
>>>>>>>> tcp.stream_depth_reached | Detect | 0
>>>>>>>> tcp.reassembly_memuse | Detect | 156557860
>>>>>>>> tcp.reassembly_gap | Detect | 3646
>>>>>>>> detect.alert | Detect | 24
>>>>>>>> decoder.pkts | RxPcapix01 | 7799419
>>>>>>>> decoder.bytes | RxPcapix01 | 6619532090
>>>>>>>> decoder.ipv4 | RxPcapix01 | 7732780
>>>>>>>> decoder.ipv6 | RxPcapix01 | 181
>>>>>>>> decoder.ethernet | RxPcapix01 | 7799419
>>>>>>>> decoder.raw | RxPcapix01 | 0
>>>>>>>> decoder.sll | RxPcapix01 | 0
>>>>>>>> decoder.tcp | RxPcapix01 | 4036503
>>>>>>>> decoder.udp | RxPcapix01 | 767312
>>>>>>>> decoder.sctp | RxPcapix01 | 0
>>>>>>>> decoder.icmpv4 | RxPcapix01 | 1957
>>>>>>>> decoder.icmpv6 | RxPcapix01 | 0
>>>>>>>> decoder.ppp | RxPcapix01 | 0
>>>>>>>> decoder.pppoe | RxPcapix01 | 0
>>>>>>>> decoder.gre | RxPcapix01 | 0
>>>>>>>> decoder.vlan | RxPcapix01 | 15588470
>>>>>>>> decoder.avg_pkt_size | RxPcapix01 | 849
>>>>>>>> decoder.max_pkt_size | RxPcapix01 | 1518
>>>>>>>> defrag.ipv4.fragments | RxPcapix01 | 0
>>>>>>>> defrag.ipv4.reassembled | RxPcapix01 | 0
>>>>>>>> defrag.ipv4.timeouts | RxPcapix01 | 0
>>>>>>>> defrag.ipv6.fragments | RxPcapix01 | 0
>>>>>>>> defrag.ipv6.reassembled | RxPcapix01 | 0
>>>>>>>> defrag.ipv6.timeouts | RxPcapix01 | 0
>>>>>>>> flow_mgr.closed_pruned | FlowManagerThread | 9036
>>>>>>>> flow_mgr.new_pruned | FlowManagerThread | 3033
>>>>>>>> flow_mgr.est_pruned | FlowManagerThread | 4478
>>>>>>>> flow.memuse | FlowManagerThread | 5401024
>>>>>>>> flow.spare | FlowManagerThread | 10034
>>>>>>>> flow.emerg_mode_entered | FlowManagerThread | 0
>>>>>>>> flow.emerg_mode_over | FlowManagerThread | 0
>>>>>>>
>>>>>>> I've now setup a rule to "filestore" the downloads so I can check them, and the stored files seem truncated.
>>>>>>>
>>>>>>> Also files-json.log continues to log "stored: false" while the files are actually saved.
>>>>>>>
>>>>>>>
>>>>>>
>>>>>> The file on the server is about 120K, but the saved files are about 4K.
>>>>>> Which also reminds me that I've never actually saw a file much bigger than a few KBs in my files dir.
>>>>>
>>>>> Did you try increasing your request-body-limit and response-body-limit?
>>>>> https://redmine.openinfosecfoundation.org/projects/suricata/wiki/File_Extraction#Settings
>>>>>
>>>>> The fact that the state is "closed" looks like a bug btw.
>>>>>
>>>>> --
>>>>> ---------------------------------------------
>>>>> Victor Julien
>>>>> http://www.inliniac.net/
>>>>> PGP: http://www.inliniac.net/victorjulien.asc
>>>>> ---------------------------------------------
>>>>>
>>>>
>>>> My request-body-limit was set to 0 (unlimited), and response-body-limit was about 3k, and I've set it now to unlimited too.
>>>> Also my stream.reassembly.depth is set to unlimited.
>>>>
>>>> Now I'm seeing this in files-json.log :
>>>>
>>>> { "id": 95268539, "timestamp": "07\/12\/2012-10:01:40.012440", "ipver": 4, "srcip": "10.128.2.35", "dstip": "10.129.23.105", "protocol": 6, "sp": 80, "dp": 53072, "http_uri": "\/test.img", "http_host": "testserver.example.com", "http_referer": "<unknown>", "filename": "\/test.img", "magic": "ASCII text", "state": "UNKNOWN", "stored": true, "size": 88654 }
>>>> { "id": 95268540, "timestamp": "07\/12\/2012-10:01:56.041302", "ipver": 4, "srcip": "10.128.2.35", "dstip": "10.129.23.105", "protocol": 6, "sp": 80, "dp": 53074, "http_uri": "\/test.img", "http_host": "testserver.example.com", "http_referer": "<unknown>", "filename": "\/test.img", "magic": "ASCII text", "state": "UNKNOWN", "stored": true, "size": 88654 }
>>>> { "id": 95268541, "timestamp": "07\/12\/2012-10:01:59.306984", "ipver": 4, "srcip": "10.128.2.35", "dstip": "10.129.23.105", "protocol": 6, "sp": 80, "dp": 53076, "http_uri": "\/test.img", "http_host": "testserver.example.com", "http_referer": "<unknown>", "filename": "\/test.img", "magic": "ASCII text", "state": "UNKNOWN", "stored": true, "size": 88654 }
>>>>
>>>> No MD5, but it says "stored:true".
>>>> The file is much bigger, but again truncated.
>>>>
>>>>
>>>> I can provide my suricata.yaml if needed.
>>>>
>>>
>>> Cool. A pcap would also be good.
>>>
>>> Btw, I noticed in your stats.log that you have quite a few
>>> tcp.reassembly_gap's. Might indicate pkt loss or stream engine running
>>> low on memory.
>>>
>>> --
>>> ---------------------------------------------
>>> Victor Julien
>>> http://www.inliniac.net/
>>> PGP: http://www.inliniac.net/victorjulien.asc
>>> ---------------------------------------------
>>
>> It seems the machine just can't keep up with the processing.
>> When I loaded just the local.rules signature file, I'm now seeing proper checksum in files-json.log, and the stored file is not truncated.
>>
>> I'm running with "ac-bs" and the machine has free memory, but probably the CPU is just not enough. (Xeon E5420 @ 2.50GHz).
>>
>
> Are you running ac-bs with:
>
> detect-engine:
> - sgh-mpm-context: full
>
> If not, try that (uses ~5GB on a 10k ruleset for me).
>
> Otherwise "ac" is going to be faster.
>
> --
> ---------------------------------------------
> Victor Julien
> http://www.inliniac.net/
> PGP: http://www.inliniac.net/victorjulien.asc
> ---------------------------------------------
>
>
>
I was running with "auto", will now try "full". Thanks.
More information about the Oisf-devel
mailing list