./scripts/start not returning to command line after containers have started #1017
|
Describe the bug
Meanwhile, the Java process is running at around 60% CPU. Btw, Malcolm version 26.04.1 has already been successfully installed and running perfectly on this exact hardware before. Expected behavior Malcolm Version:
How are you running Malcolm? Additional context |
Replies: 4 comments 12 replies
|
Same Problem with 26.06. I also changed the OS from Ubuntu 26.04 LTS to 24.04 LTS.
|
|
Those debug messages don't necessarily indicate a startup problem to me, so let's see if we can figure out what we think is hanging specifically. First, run $ ./scripts/status
NAME IMAGE COMMAND SERVICE CREATED STATUS PORTS
malcolm-api-1 ghcr.io/idaholab/malcolm/api:26.06.0 "/usr/bin/tini -- /u…" api 5 minutes ago Up 5 minutes (healthy) 5000/tcp
malcolm-arkime-1 ghcr.io/idaholab/malcolm/arkime:26.06.0 "/usr/bin/tini -- /u…" arkime 5 minutes ago Up 5 minutes (healthy) 8000/tcp, 8005/tcp, 8081/tcp
malcolm-arkime-live-1 ghcr.io/idaholab/malcolm/arkime:26.06.0 "/usr/bin/tini -- /u…" arkime-live 5 minutes ago Up 5 minutes (healthy)
malcolm-dashboards-1 ghcr.io/idaholab/malcolm/dashboards:26.06.0 "/usr/bin/tini -- /u…" dashboards 5 minutes ago Up 5 minutes (healthy) 5601/tcp
malcolm-dashboards-helper-1 ghcr.io/idaholab/malcolm/dashboards-helper:26.06.0 "/usr/bin/tini -- /u…" dashboards-helper 5 minutes ago Up 5 minutes (healthy) 28991/tcp
malcolm-filebeat-1 ghcr.io/idaholab/malcolm/filebeat-oss:26.06.0 "/usr/bin/tini -- /u…" filebeat 5 minutes ago Up 5 minutes (healthy) 0.0.0.0:514->514/tcp, 0.0.0.0:5045->5045/tcp, 0.0.0.0:514->514/udp
malcolm-filescan-1 ghcr.io/idaholab/malcolm/filescan:26.06.0 "/usr/bin/tini -- /u…" filescan 5 minutes ago Up 5 minutes (healthy) 8001/tcp, 8006/tcp
malcolm-freq-1 ghcr.io/idaholab/malcolm/freq:26.06.0 "/usr/bin/tini -- /u…" freq 5 minutes ago Up 5 minutes (healthy) 10004/tcp
malcolm-htadmin-1 ghcr.io/idaholab/malcolm/htadmin:26.06.0 "/usr/bin/tini -- /u…" htadmin 5 minutes ago Up 5 minutes (healthy) 80/tcp
malcolm-keycloak-1 ghcr.io/idaholab/malcolm/keycloak:26.06.0 "/usr/bin/tini -- /u…" keycloak 5 minutes ago Up 5 minutes (healthy) 8080/tcp, 8443/tcp, 9000/tcp
malcolm-logstash-1 ghcr.io/idaholab/malcolm/logstash-oss:26.06.0 "/usr/bin/tini -- /u…" logstash 5 minutes ago Up 5 minutes (healthy) 9001/tcp, 0.0.0.0:5044->5044/tcp, 9600/tcp
malcolm-netbox-1 ghcr.io/idaholab/malcolm/netbox:26.06.0 "/usr/bin/tini -- /u…" netbox 5 minutes ago Up 5 minutes (healthy) 9001/tcp
malcolm-nginx-proxy-1 ghcr.io/idaholab/malcolm/nginx-proxy:26.06.0 "/sbin/tini -- /usr/…" nginx-proxy 5 minutes ago Up 5 minutes (healthy)
malcolm-opensearch-1 ghcr.io/idaholab/malcolm/opensearch:26.06.0 "/usr/bin/tini -- /u…" opensearch 5 minutes ago Up 5 minutes (healthy) 9200/tcp, 9300/tcp, 9600/tcp, 9650/tcp
malcolm-pcap-capture-1 ghcr.io/idaholab/malcolm/pcap-capture:26.06.0 "/usr/bin/tini -- /u…" pcap-capture 5 minutes ago Up 5 minutes (healthy)
malcolm-pcap-monitor-1 ghcr.io/idaholab/malcolm/pcap-monitor:26.06.0 "/usr/bin/tini -- /u…" pcap-monitor 5 minutes ago Up 5 minutes (healthy) 30441/tcp
malcolm-postgres-1 ghcr.io/idaholab/malcolm/postgresql:26.06.0 "/sbin/tini -- /usr/…" postgres 5 minutes ago Up 5 minutes (healthy) 5432/tcp
malcolm-strelka-backend-1 ghcr.io/idaholab/malcolm/strelka-backend:26.06.0 "/usr/bin/tini -- /u…" strelka-backend 5 minutes ago Up 5 minutes (healthy)
malcolm-strelka-frontend-1 ghcr.io/idaholab/malcolm/strelka-frontend:26.06.0 "/sbin/tini -- /usr/…" strelka-frontend 5 minutes ago Up 5 minutes (healthy) 57314/tcp
malcolm-strelka-manager-1 ghcr.io/idaholab/malcolm/strelka-manager:26.06.0 "/sbin/tini -- /usr/…" strelka-manager 5 minutes ago Up 5 minutes (healthy)
malcolm-suricata-1 ghcr.io/idaholab/malcolm/suricata:26.06.0 "/usr/bin/tini -- /u…" suricata 5 minutes ago Up 5 minutes (healthy)
malcolm-suricata-live-1 ghcr.io/idaholab/malcolm/suricata:26.06.0 "/usr/bin/tini -- /u…" suricata-live 5 minutes ago Up 5 minutes (healthy)
malcolm-upload-1 ghcr.io/idaholab/malcolm/file-upload:26.06.0 "/usr/bin/tini -- /u…" upload 5 minutes ago Up 5 minutes (healthy) 80/tcp, 0.0.0.0:8022->22/tcp
malcolm-valkey-1 ghcr.io/idaholab/malcolm/valkey:26.06.0 "/sbin/tini -- /usr/…" valkey 5 minutes ago Up 5 minutes (healthy) 6379/tcp
malcolm-valkey-cache-1 ghcr.io/idaholab/malcolm/valkey:26.06.0 "/sbin/tini -- /usr/…" valkey-cache 5 minutes ago Up 5 minutes (healthy) 6379/tcp
malcolm-zeek-1 ghcr.io/idaholab/malcolm/zeek:26.06.0 "/usr/bin/tini -- /u…" zeek 5 minutes ago Up 5 minutes (healthy)
malcolm-zeek-live-1 ghcr.io/idaholab/malcolm/zeek:26.06.0 "/usr/bin/tini -- /u…" zeek-live 5 minutes ago Up 5 minutes (healthy) Next, can you hit your Malcolm IP address or host name? If you can, go to {
"arkime": true,
"dashboards": true,
"dashboards_maps": true,
"extracted_files": true,
"filebeat_tcp": true,
"filescan": true,
"freq": true,
"logstash_lumberjack": true,
"logstash_pipelines": true,
"netbox": true,
"opensearch": true,
"pcap_monitor": true,
"redis": true,
"redis_cache": true,
"strelka": true
}If you can't hit your Malcolm IP or hostname, run this command from the command line in the Malcolm installation directory. Let's also check resources. Run Once we figure out what container or process are "hung" we can dig into why. |
|
I think the problem might be in the control.py master script, specifically the start() function. Considering the fact that stop(), status() are working properly. All containers are tagged as healthy. The below entries and similar are getting displayed when running the start or restart function. logstash-1 | [2026-06-04T10:20:06,080][WARN ][org.logstash.plugins.pipeline.AbstractPipelineBus] Attempted to send event to 'zeek-parse' but that address was unavailable. Maybe the destination pipeline is down or stopping? Will Retry. |
|
If the containers are healthy, what makes you think the startup is hung at all? Can you access Malcolm via the web interface? |
|
I think I understand what's going on now.. simply invoking ./script/start without the -q (QUIET) option, will show logs from Malcolm containers that are starting up and somehow does not exit and keeps showing the logs from certain containers, leading to a mistaken assumption that the startup got hung. With the -q parameter, the script exits properly. |
|
I think you're right about what you're seeing and your assumption. However, there is code in the control script that is supposed to eventually dump back out to the command line, even without Which is what would cause it to stop printing out the debug startup logs. |
|
last line logstash-1 | [2026-06-05T14:20:11,461][WARN ][logstash.outputs.opensearch] Could not index event to OpenSearch. {status: 400, action: ["index", {_id: "260605-xGjrtsGexy3WSfHY_rR9LA", _index: "arkime_sessions3-260605", routing: nil}, {"length" => "0", "zeek" => {"ts" => "2026-06-05T14:19:57.356Z", "uid" => ["Cmp7yt1QLxhJA54Qtl"], "dhcp" => {"lease_time" => 0.36e4, "assigned_ip" => "112.205.130.235", "msg_types" => ["REQUEST", "ACK"], "duration" => 0.2614903450012207e-1, "mac" => "bc:24:11:7c:e3:3b", "host_name" => "OPNsense"}}, "source" => {"as" => {"full" => "AS9299 Philippine Long Distance Telephone Company"}, "port" => "112.205.128.1", "oui" => "Proxmox Server Solutions GmbH", "segment" => {"name" => "public"}, "ip" => "112.205.130.235", "geo" => {"continent_code" => "AS", "postal_code" => "1500", "region_code" => "00", "region_name" => "Metro Manila", "country_iso_code" => "PH", "country_code3" => "PH", "location" => {"lat" => 14.5832, "lon" => 121.0409}, "country_code2" => "PH", "longitude" => 121.0409, "latitude" => 14.5832, "timezone" => "Asia/Manila", "country_name" => "Philippines", "ip" => "112.205.130.235", "city_name" => "Mandaluyong City"}, "mac" => "bc:24:11:7c:e3:3b"}, "@Version" => "1", "node" => "malcolm", "lastPacket" => "1780669197356", "firstPacket" => 1780669197356, "srcOui" => ["Proxmox Server Solutions GmbH"], "input" => {}, "client" => {"domain" => "OPNsense"}, "related" => {"hosts" => ["OPNsense"], "ip" => ["112.205.130.235"], "mac" => ["bc:24:11:7c:e3:3b"], "oui" => ["Proxmox Server Solutions GmbH"]}, "ecs" => {"version" => "8.0.0"}, "timestamp" => 1780669197356, "ipProtocol" => "17", "host" => {"name" => "malcolm"}, "event" => {"end" => "1780669197356", "severity_tags" => ["External traffic"], "dataset" => "dhcp", "kind" => "event", "ingested" => 2026-06-05T14:20:11.120Z, "result" => ["Success"], "provider" => "zeek", "risk_score_norm" => 20.0, "id" => ["Cmp7yt1QLxhJA54Qtl"], "category" => ["network"], "hash" => "xGjrtsGexy3WSfHY_rR9LA", "action" => ["REQUEST", "ACK"], "start" => "1780669197356", "risk_score" => 20.0, "severity" => 20}, "log" => {"file" => {"path" => "dhcp.log"}}, "dhcp" => {"mac" => ["bc:24:11:7c:e3:3b"], "oui" => "Proxmox Server Solutions GmbH", "host" => ["OPNsense", "112.205.130.235"], "type" => ["REQUEST", "ACK"]}, "protocol" => ["udp", "dhcp"], "tags" => ["_mutate_error"], "@timestamp" => 2026-06-05T14:19:57.356Z, "rootId" => "Cmp7yt1QLxhJA54Qtl", "network" => {"application" => "dhcp", "iana_number" => ["17"], "direction" => "external", "transport" => "udp", "type" => "ipv4", "protocol" => ["dhcp"]}, "agent" => {"name" => "malcolm"}}], response: {"index" => {"_index" => "arkime_sessions3-260605", "_id" => "260605-xGjrtsGexy3WSfHY_rR9LA", "status" => 400, "error" => {"type" => "mapper_parsing_exception", "reason" => "failed to parse field [source.port] of type [long] in document with id '260605-xGjrtsGexy3WSfHY_rR9LA'. Preview of field's value: '112.205.128.1'", "caused_by" => {"type" => "illegal_argument_exception", "reason" => "For input string: "112.205.128.1""}}}}} the script never exited |
|
First, and unrelated to this discussion, but you're using More related to the script exiting like we've been talking about: $ docker compose --profile=malcolm logs logstash | grep running_pipelines
logstash-1 | [2026-06-05T13:58:01,286][INFO ][logstash.agent ] Pipelines running {count: 7, running_pipelines: [:"malcolm-output", :"malcolm-input", :"malcolm-filescan", :"malcolm-suricata", :"malcolm-beats", :"malcolm-enrichment", :"malcolm-zeek"], non_running_pipelines: []}If you run that command, do you see a similar line of output? |
|
This before the could not index thingy logstash-1 | [2026-06-05T02:08:32,769][WARN ][org.logstash.plugins.pipeline.AbstractPipelineBus] Attempted to send event to 'zeek-parse' but that address was unavailable. Maybe the destination pipeline is down or stopping? Will Retry. With regards to your question... (using docker compose --profile=malcolm logs logstash | grep running_pipelines) logstash-1 | [2026-06-05T02:08:40,878][INFO ][logstash.agent ] Pipelines running {count: 7, running_pipelines: [:"malcolm-output", :"malcolm-input", :"malcolm-filescan", :"malcolm-suricata", :"malcolm-beats", :"malcolm-enrichment", :"malcolm-zeek"], non_running_pipelines: []} |
|
Here my Output: xxxxxxxxxx@malcolm:~/Malcolm$ ./scripts/status xxxxxxxxxx@malcolm: It seems that Malcolm is running, Slow but it is running. Now the script "./scripts/start" is still running. But it shows the webrequest and so on. |
|
So in the meanwhile everthing is running fine. I'can quit the running startup script if all conatiners are healthy. It looks like the script does not exit if everything is running fine. Maybe this could be a bug. |
|
Looking closer at the logstash output with the latest version, I believe you are right. I'll get it fixed for the next release, thank you. |
|
The Logstash output we were looking for changed format. I've fixed it for the next release, see #1025. |
|
#1025 fixes the issue. |
I think I understand what's going on now.. simply invoking ./script/start without the -q (QUIET) option, will show logs from Malcolm containers that are starting up and somehow does not exit and keeps showing the logs from certain containers, leading to a mistaken assumption that the startup got hung. With the -q parameter, the script exits properly.