Agent status remains "new" after container execution with MQTT error

Agents remains "new" after running the agent when the agent has a MQTT problem

Important: this seems to be intermittent..

I could see it in Orb:

And Logs (other agent):

14:02:13 - ERROR - Agent did not get 'online' after 10 seconds, but was 'new'.Agent: {
    "id": "cd0e5759-c915-4c33-9566-580e3c4e168d",
    "name": "test_agent_name_vQhxvAiguB",
    "state": "new",
    "channel_id": "32105ab1-4ad0-4ef6-92c0-cf32ef0a1e34",
    "agent_tags": {},
    "orb_tags": {
        "test_tag_JRXtUt": "test_tag_ItKF",
        "test_tag_KOzWkQ": "test_tag_kLZf"
    },
    "agent_metadata": {
        "backends": {
            "pktvisor": {
                "data": {
                    "taps": {
                        "default_pcap": {
                            "config": {
                                "iface": "wlo1"
                            },
                            "input_type": "pcap",
                            "interface": "visor.module.input/1.0"
                        }
                    }
                },
                "version": "4.2.0-develop-146131e"
            }
        },
        "orb_agent": {
            "version": "0.16.0-develop"
        }
    },
    "last_hb_data": {
        "backend_state": {
            "pktvisor": {
                "state": "running"
            }
        },
        "group_state": {},
        "policy_state": {}
    },
    "ts_created": "2022-06-13T17:01:57.123257Z",
    "ts_last_hb": "2022-06-13T17:01:59.20776Z"
}.Agent logs: ['{"level":"info","ts":1655139717.4364607,"caller":"agent/agent.go:65","msg":"using local config db","filename":"./orb-agent.db"}', '{"level":"info","ts":1655139717.4369404,"caller":"agent/agent.go:103","msg":"agent started","version":"0.16.0-develop"}', '{"level":"info","ts":1655139717.4369607,"caller":"agent/agent.go:79","msg":"registered backends","values":["pktvisor"]}', '{"level":"info","ts":1655139717.4369693,"caller":"agent/agent.go:80","msg":"requested backends","values":{"pktvisor":{"api_host":"localhost","api_port":"10863","binary":"/usr/local/sbin/pktvisord","config_file":"/tmp/orb-agent-pktvisor-conf.WA7qVj"}}}', '{"level":"info","ts":1655139717.4370236,"caller":"pktvisor/pktvisor.go:240","msg":"pktvisor startup","arguments":["--admin-api","-l","localhost","-p","10863","--config","/tmp/orb-agent-pktvisor-conf.WA7qVj"]}', '{"level":"info","ts":1655139717.445239,"caller":"pktvisor/pktvisor.go:258","msg":"pktvisor stdout","log":"[2022-06-13 17:01:57.445] [visor] [info] pktvisor 4.2.0-develop-146131e starting up"}', '{"level":"info","ts":1655139717.4452875,"caller":"pktvisor/pktvisor.go:258","msg":"pktvisor stdout","log":"[2022-06-13 17:01:57.445] [visor] [info] Load input stream plugin: dnstap visor.module.input/1.0"}', '{"level":"info","ts":1655139717.4452956,"caller":"pktvisor/pktvisor.go:258","msg":"pktvisor stdout","log":"[2022-06-13 17:01:57.445] [visor] [info] Load input stream plugin: flow visor.module.input/1.0"}', '{"level":"info","ts":1655139717.445302,"caller":"pktvisor/pktvisor.go:258","msg":"pktvisor stdout","log":"[2022-06-13 17:01:57.445] [visor] [info] Load input stream plugin: mock visor.module.input/1.0"}', '{"level":"info","ts":1655139717.445308,"caller":"pktvisor/pktvisor.go:258","msg":"pktvisor stdout","log":"[2022-06-13 17:01:57.445] [visor] [info] Load input stream plugin: pcap visor.module.input/1.0"}', '{"level":"info","ts":1655139717.4453137,"caller":"pktvisor/pktvisor.go:258","msg":"pktvisor stdout","log":"[2022-06-13 17:01:57.445] [visor] [info] Load input stream plugin: sflow visor.module.input/1.0"}', '{"level":"info","ts":1655139717.4453201,"caller":"pktvisor/pktvisor.go:258","msg":"pktvisor stdout","log":"[2022-06-13 17:01:57.445] [visor] [info] Load stream handler plugin: dhcp visor.module.handler/1.0"}', '{"level":"info","ts":1655139717.4453273,"caller":"pktvisor/pktvisor.go:258","msg":"pktvisor stdout","log":"[2022-06-13 17:01:57.445] [visor] [info] Load stream handler plugin: dns visor.module.handler/1.0"}', '{"level":"info","ts":1655139717.4453335,"caller":"pktvisor/pktvisor.go:258","msg":"pktvisor stdout","log":"[2022-06-13 17:01:57.445] [visor] [info] Load stream handler plugin: flow visor.module.handler/1.0"}', '{"level":"info","ts":1655139717.445342,"caller":"pktvisor/pktvisor.go:258","msg":"pktvisor stdout","log":"[2022-06-13 17:01:57.445] [visor] [info] Load stream handler plugin: input_resources visor.module.handler/1.0"}', '{"level":"info","ts":1655139717.445348,"caller":"pktvisor/pktvisor.go:258","msg":"pktvisor stdout","log":"[2022-06-13 17:01:57.445] [visor] [info] Load stream handler plugin: net visor.module.handler/1.0"}', '{"level":"info","ts":1655139717.4453554,"caller":"pktvisor/pktvisor.go:258","msg":"pktvisor stdout","log":"[2022-06-13 17:01:57.445] [visor] [info] Load stream handler plugin: pcap visor.module.handler/1.0"}', '{"level":"info","ts":1655139717.4453616,"caller":"pktvisor/pktvisor.go:258","msg":"pktvisor stdout","log":"[2022-06-13 17:01:57.445] [visor] [info] Initialize server control plane"}', '{"level":"info","ts":1655139717.4453688,"caller":"pktvisor/pktvisor.go:258","msg":"pktvisor stdout","log":"[2022-06-13 17:01:57.445] [visor] [info] Registering DELETE /api/v1/server"}', '{"level":"info","ts":1655139717.4453747,"caller":"pktvisor/pktvisor.go:258","msg":"pktvisor stdout","log":"[2022-06-13 17:01:57.445] [visor] [info] Registering GET /api/v1/metrics/app"}', '{"level":"info","ts":1655139717.445382,"caller":"pktvisor/pktvisor.go:258","msg":"pktvisor stdout","log":"[2022-06-13 17:01:57.445] [visor] [info] Registering GET /api/v1/metrics/rates"}', '{"level":"info","ts":1655139717.4453883,"caller":"pktvisor/pktvisor.go:258","msg":"pktvisor stdout","log":"[2022-06-13 17:01:57.445] [visor] [info] Registering GET /api/v1/metrics/bucket/(\\\\d+)"}', '{"level":"info","ts":1655139717.4453967,"caller":"pktvisor/pktvisor.go:258","msg":"pktvisor stdout","log":"[2022-06-13 17:01:57.445] [visor] [info] Registering GET /api/v1/metrics/window/(\\\\d+)"}', '{"level":"info","ts":1655139717.445418,"caller":"pktvisor/pktvisor.go:258","msg":"pktvisor stdout","log":"[2022-06-13 17:01:57.445] [visor] [info] enabling prometheus metrics for \\"default\\" policy on: /metrics"}', '{"level":"info","ts":1655139717.445483,"caller":"pktvisor/pktvisor.go:258","msg":"pktvisor stdout","log":"[2022-06-13 17:01:57.445] [visor] [info] Registering GET /metrics"}', '{"level":"info","ts":1655139717.4454916,"caller":"pktvisor/pktvisor.go:258","msg":"pktvisor stdout","log":"[2022-06-13 17:01:57.445] [visor] [info] Registering GET /api/v1/taps"}', '{"level":"info","ts":1655139717.4454973,"caller":"pktvisor/pktvisor.go:258","msg":"pktvisor stdout","log":"[2022-06-13 17:01:57.445] [visor] [info] Registering GET /api/v1/policies"}', '{"level":"info","ts":1655139717.4455028,"caller":"pktvisor/pktvisor.go:258","msg":"pktvisor stdout","log":"[2022-06-13 17:01:57.445] [visor] [info] Registering POST /api/v1/policies"}', '{"level":"info","ts":1655139717.445508,"caller":"pktvisor/pktvisor.go:258","msg":"pktvisor stdout","log":"[2022-06-13 17:01:57.445] [visor] [info] Registering GET /api/v1/policies/([a-zA-Z_][a-zA-Z0-9_-]*)"}', '{"level":"info","ts":1655139717.445542,"caller":"pktvisor/pktvisor.go:258","msg":"pktvisor stdout","log":"[2022-06-13 17:01:57.445] [visor] [info] Registering DELETE /api/v1/policies/([a-zA-Z_][a-zA-Z0-9_-]*)"}', '{"level":"info","ts":1655139717.4456487,"caller":"pktvisor/pktvisor.go:258","msg":"pktvisor stdout","log":"[2022-06-13 17:01:57.445] [visor] [info] Registering GET /api/v1/policies/([a-zA-Z_][a-zA-Z0-9_-]*)/metrics/(window|bucket)/(\\\\d+)"}', '{"level":"info","ts":1655139717.4457803,"caller":"pktvisor/pktvisor.go:258","msg":"pktvisor stdout","log":"[2022-06-13 17:01:57.445] [visor] [info] Registering GET /api/v1/policies/([a-zA-Z_][a-zA-Z0-9_-]*)/metrics/prometheus"}', '{"level":"info","ts":1655139717.445872,"caller":"pktvisor/pktvisor.go:258","msg":"pktvisor stdout","log":"[2022-06-13 17:01:57.445] [visor] [info] tap [default_pcap]: parsing"}', '{"level":"info","ts":1655139717.4460354,"caller":"pktvisor/pktvisor.go:258","msg":"pktvisor stdout","log":"[2022-06-13 17:01:57.446] [visor] [info] tap [default_pcap]: loaded, type pcap"}', '{"level":"info","ts":1655139717.4461184,"caller":"pktvisor/pktvisor.go:258","msg":"pktvisor stdout","log":"[2022-06-13 17:01:57.446] [visor] [info] sending anonymous usage metrics (once/day, use --no-track to disable): e131641-poleved-0.2.4.pktvisord.metrics.pktvisor.dev."}', '{"level":"info","ts":1655139717.6011207,"caller":"pktvisor/pktvisor.go:258","msg":"pktvisor stdout","log":"[2022-06-13 17:01:57.601] [visor] [info] web server listening on localhost:10863"}', '{"level":"info","ts":1655139718.437439,"caller":"pktvisor/pktvisor.go:287","msg":"pktvisor process started","pid":20}', '{"level":"info","ts":1655139718.4375257,"caller":"cloud_config/cloud_config.go:173","msg":"using explicitly specified cloud configuration","address":"tls://orb.live:8883","id":"cd0e5759-c915-4c33-9566-580e3c4e168d"}', '{"level":"info","ts":1655139719.2853818,"caller":"pktvisor/pktvisor.go:258","msg":"pktvisor stdout","log":"[2022-06-13 17:01:59.285] [visor] [info] REQUEST: GET /api/v1/metrics/app 200"}', '{"level":"info","ts":1655139719.2857246,"caller":"pktvisor/pktvisor.go:258","msg":"pktvisor stdout","log":"[2022-06-13 17:01:59.285] [visor] [info] REQUEST: GET /api/v1/taps 200"}', '{"level":"info","ts":1655139719.2857878,"caller":"agent/rpc_to.go:48","msg":"sending capabilities","value":"{\\"schema_version\\":\\"1.0\\",\\"orb_agent\\":{\\"version\\":\\"0.16.0-develop\\"},\\"agent_tags\\":null,\\"backends\\":{\\"pktvisor\\":{\\"version\\":\\"4.2.0-develop-146131e\\",\\"data\\":{\\"taps\\":{\\"default_pcap\\":{\\"config\\":{\\"iface\\":\\"wlo1\\"},\\"input_type\\":\\"pcap\\",\\"interface\\":\\"visor.module.input/1.0\\"}}}}}}"}', '{"level":"info","ts":1655139719.7472813,"caller":"agent/comms.go:141","msg":"completed RPC subscription to group","group_id":"eb5239c9-91ec-4dbe-9ae9-55c5fad33821","group_name":"test_group_name_new_name_lkjQo","topic":"channels/511bcac4-fc91-4c45-82a1-7c759f25325d/messages/fromcore"}', ''].
Expected: 'online'
     but: was 'new'
NoneType: None

Grafana is showing this log:


{"log":"{\"level\":\"warn\",\"message\":\"Broken connection for client: 55020700-13e3-427d-b60d-b2135635e5e6 with error: failed proxying from MQTT broker to MQTT client : malformed topic\",\"ts\":\"2022-06-13T13:36:19.115575996Z\"}\r\n","stream":"stdout","time":"2022-06-13T13:36:19.11579673Z"}

orb-community / orb

Agent status remains "new" after container execution with MQTT error #1334