Dashboard data stopping after short period of runtime

[etherxrally]

Hello everyone, I've got a single node instance that i am using to capture some light traffic. If I restart Malcolm using the script ./restart I get data for a short period of time. maybe an hour or so then it stops. Arkime continues to show data but its not making it to the dashboard. Portainer shows all instances are healthy. Any suggestions where I should start looking? PCAP-capture-1, Arkime-live-1, Zeek live-1, and suricata-live-1 don't show (healthy) when running ./status but they do show as "Up". Any help or direction is appreciated. Thank you.

[mmguero]

Those live containers showing "up" is expected. I think the first place to start would be examining the debug logs for a few different containers to try to see if anything's happening there. Let's start here: run ./scripts/logs -s opensearch filebeat logstash and attach the results here, then I'll try to help you debug them. Those are the containers that are going to be involved in log ingestion.

Also, let's check the results of this command, run in the Malcolm installation directory:

• for CONTAINER in pcap-capture zeek-live suricata-live; do echo "$CONTAINER ----------"; docker compose exec "$CONTAINER" supervisorctl status; docker compose exec "$CONTAINER" ps axf; done

That should give me an idea of the processes running related to capture.

[etherxrally]

slight modification of docker-compose rather than docker compose if that matters but I think this is what you were after. The issue just came back today after it had run for about 4 days without issue. Im gathering the other files. IS there anything specific I should be looking for? Eth1 is the capture interface while our eth0 is just management.

pcap-capture ----------
netsniff:netsniff-eth1 RUNNING pid 77, uptime 4 days, 5:18:58
netsniff-roll RUNNING pid 78, uptime 4 days, 5:18:58
tcpdump:tcpdump-eth1 STOPPED Not started
PID TTY STAT TIME COMMAND
153257 pts/1 Rs+ 0:00 ps axf
1 pts/0 Ss 0:04 /usr/bin/tini -- /usr/local/bin/docker-uid-gid-setup.sh /usr/local/bin/service_check_passthrough.sh -s pcap-capture /usr/local/bin/supervisor.sh
7 pts/0 S+ 0:00 /bin/bash /usr/local/bin/docker-uid-gid-setup.sh /usr/local/bin/service_check_passthrough.sh -s pcap-capture /usr/local/bin/supervisor.sh
29 pts/0 S+ 0:00 _ su -s /bin/bash -p root
31 pts/0 S+ 0:00 _ bash
34 pts/0 S+ 0:00 _ /bin/bash /usr/local/bin/supervisor.sh
76 pts/0 S+ 0:34 _ /usr/bin/python3 /usr/bin/supervisord -c /etc/supervisord.conf -n
77 pts/0 SL 0:33 _ /usr/sbin/netsniff-ng -i eth1 -T 0xa1b2c3d4 -o /pcap -P mnetsniff-eth1_ -F 4096MiB --silent
78 pts/0 S 0:25 _ /bin/bash /usr/local/bin/netsniff-roll.sh
153250 pts/0 S 0:00 _ sleep 10
zeek-like ----------
service "zeek-like" is not running
service "zeek-like" is not running
suricata-live ----------
cron RUNNING pid 769, uptime 4 days, 5:18:37
live-suricata RUNNING pid 770, uptime 4 days, 5:18:37
pcap-suricata STOPPED Not started
PID TTY STAT TIME COMMAND
986 pts/1 Rs+ 0:00 ps axf
1 pts/0 Ss 0:04 /usr/bin/tini -- /usr/local/bin/docker-uid-gid-setup.sh /usr/local/bin/service_check_passthrough.sh -s suricata /usr/local/bin/docker_entrypoint.sh /usr/bin
7 pts/0 S+ 0:00 /bin/bash /usr/local/bin/docker-uid-gid-setup.sh /usr/local/bin/service_check_passthrough.sh -s suricata /usr/local/bin/docker_entrypoint.sh /usr/bin/superv
753 pts/0 S+ 0:00 _ su -s /bin/bash -p root
755 pts/0 S+ 0:00 _ bash
758 pts/0 S+ 0:34 _ /usr/bin/python3 /usr/bin/supervisord -c /etc/supervisord.conf -n
769 pts/0 Sl 0:01 _ /usr/local/bin/supercronic -json /etc/crontab
770 pts/0 Sl 19:05 _ /usr/bin/suricata -v -c /etc/suricata/suricata.yaml -l /var/log/suricata/live --af-packet

[mmguero]

zeek-like should be zeek-live there, but from what we're seeing in the other containers it does appear that the capture processes are running as expected.

As far as what we're looking for in the other logs, in the opensearch and logstash containers we'd just be looking for persistent errors that keep going long after the startup should be finished (some errors during initial startup while the containers are getting synced to each other is pretty normal). For the filebeat container, periodically we should be seeing messages like "harvesting started" and "harvesting finished" (not in front of an instance right now, so that might not be the exact wording but it's close) as filebeat processes new files it sees.

[etherxrally]

Logging.txt

Here is a section that includes the Harvester and a quick glance suggests the rest is similar. The Failed actions seem to be persistent and exist when its working and when its not working so while it doesn't look right im not sure if it's the problem or not. Thank you for taking time to review. I appreciate it.

[mmguero]

Looking at this log, the culprit seems to be this:

$ grep ':error' Logging.txt  | sed "s/.*:error=>//"
{"type"=>"cluster_block_exception", "reason"=>"index [arkime_sessions3-700101] blocked by: [FORBIDDEN/8/index write (api)];"}}

This isn't something I've ever seen before. Looking at one full instance of the error:

malcolm-logstash-1            | [2024-12-16T13:36:00,397][INFO ][logstash.outputs.opensearch] Retrying failed action {:status=>403, :action=>["index", {:_id=>"700101-N0yHMVhbVUis12pVMuTlYA", :_index=>"arkime_sessions3-700101", :routing=>nil}, {"timestamp"=>30570, "client"=>{"bytes"=>0}, "server"=>{"bytes"=>0}, "tags"=>[], "log"=>{"file"=>{"path"=>"conn.log"}}, "length"=>0, "@timestamp"=>1970-01-01T00:00:30.570Z, "firstPacket"=>30570, "network"=>{"type"=>"ipv6", "packets"=>0, "protocol"=>["S0"], "direction"=>"external", "bytes"=>0, "application"=>"S0", "vlan"=>{"id"=>["1:Sk2DhcApLnPDKQGoDXKRLWNZEjc="]}}, "input"=>{}, "zeek"=>{"ts"=>"1970-01-01T00:00:30.570Z", "uid"=>"2375", "conn"=>{"history"=>"0", "local_resp"=>"40", "missed_bytes"=>"0", "vlan"=>"1:Sk2DhcApLnPDKQGoDXKRLWNZEjc=", "tunnel_parents"=>["ca:fe:ca:fe:ca:fe"], "resp_bytes"=>"0", "orig_bytes"=>"F", "conn_state"=>"S", "local_orig"=>"1", "resp_ip_bytes"=>"b0:aa:77:9d:5b:a0", "duration"=>"F"}}, "@version"=>"1", "related"=>{"ip"=>["tcp"]}, "rootId"=>"ca:fe:ca:fe:ca:fe", "agent"=>{"name"=>"HOSTNAME"}, "destination"=>{"bytes"=>0}, "protocol"=>["S0"], "source"=>{"ip"=>"tcp", "geo"=>{}}, "ecs"=>{"version"=>"8.0.0"}, "lastPacket"=>30570, "host"=>{"name"=>"HOSTNAME"}, "totDataBytes"=>0, "node"=>"HOSTNAME", "event"=>{"severity"=>20, "severity_tags"=>["External traffic"], "category"=>["network"], "kind"=>"event", "risk_score"=>20.0, "ingested"=>2024-12-15T15:00:16.698Z, "provider"=>"zeek", "id"=>["2375"], "start"=>"30570", "risk_score_norm"=>20.0, "end"=>"30570", "dataset"=>"conn", "hash"=>"N0yHMVhbVUis12pVMuTlYA", "duration"=>0}}], :error=>{"type"=>"cluster_block_exception", "reason"=>"index [arkime_sessions3-700101] blocked by: [FORBIDDEN/8/index write (api)];"}}

The first thing that jumps out here is the timestamp: 1970-01-01T00:00:30.570Z. Why does Zeek start seeing timestamps in your network traffic that are invalid (unless we time traveled back to 1970)? I'm sort of assuming it's this wonky date that's somehow resulting in opensearch giving us the "forbidden" result as it tries to write to the arkime_sessions3-700101 (january 1, 1970) index.

Is the date/time set correctly on all hardware involved? Any ideas why it might be seeing this invalid timestamp in traffic?

[etherxrally]

Interesting, This is all running on a single VM, not a cluster so I would expect all the times to be the same. I am guessing that time stamp is coming from arkime correct? If I connect to Arkime-1 and arkime-live-1 and run a date command it is all correct. Or do you think this date is from something else?

[mmguero]

No, in this case those messages we're seeing there are data coming from Zeek logs. You could look at the .log files down in the subfolders underneath the ./zeek-logs/ directory, inspect a few of them and see if the timestamps are actually bogus.

[etherxrally]

Looking at the log files the #open dates seem correct (Eg 2024-12-17-*06-00-01) and the time stamps seem ok on each entry (Eg 1734415153.235714). One thing that seems strange to me is that when run "time" from the containers they all say:
real 0m0.000s
user 0m0.000s
sys 0m0.000s

Im not sure if that is normal behavior for a containers. I expected them to be synced with the host machine.

[mmguero]

time isn't a command to get the time, it's a command to time something. You'd want to run date, although based on what you said I don't think the system time is an issue. I need to think about this, I'll try to get back with some other ideas for you tomorrow.

[etherxrally]

thank you. Considering a restart brings the service back temporarily, I'm currently rebooting containers to see which one restores service in hopes that it might provide a better indication of what might be going on based on what that container handles. Not very elegant, I know. And thanks for the clarification on time.

[mmguero]

Yeah, sure. You can use ./scripts/restart -s service as a shortcut to restart a certain container (e.g., ./scripts/restart -s filebeat).

[mmguero]

The only other thing I could think of maybe is to run docker-compose logs and pipe that output to a file, then look for the first instance of that cluster_block_exception error and see if there are any clues around there that indicate what precipitated it. I'm not sure what would cause the data to be processing correctly and then suddenly go wonky.