The mqtt plugin will automatically exit and reload

jerryma0912 commented 1 year ago

System: ubuntu 18.04
Architecture: arm64
Version: latest

description：

The mqtt northbound plug-in sends 6 requests at the same time by reading the Topic: /neuron/mqtt/read/req. Even if the response is not complete, there will be a neuron restart problem, but it is normal in some cases, and the response will be passed topic: /neuron/mqtt/read/resp responds with 6 results. mqtt北向插件，通过读Topic：/neuron/mqtt/read/req 同时发送6条请求，偶现在未完全响应的情况下，出现neuron restart的问题，但在部分情况下是正常的，即会通过响应topic：/neuron/mqtt/read/resp响应6条结果。
The above problems are not inevitable, but during my test, it has happened 3 times within 12 hours. 上述问题非必现，但我在测试过程中，12小时内已经发生了3次。

LOG::

2023-09-07 20:00:00 [DEBUG] mqtt_client.c:253 pub [/neuron/mqtt/test/node_3, QoS0] 871 bytes 2023-09-07 20:00:00 [DEBUG] mqtt_client.c:515 recv [/neuron/mqtt/read/req, QoS0] 83 bytes 2023-09-07 20:00:00 [NOTICE] mqtt_handle.c:244 read uuid:8161c099-4c23-4425-9c21-da3f8655f671, group:metG1_1, node:test 2023-09-07 20:00:00 [DEBUG] mqtt_client.c:515 recv [/neuron/mqtt/read/req, QoS0] 83 bytes 2023-09-07 20:00:00 [DEBUG] mqtt_client.c:515 recv [/neuron/mqtt/read/req, QoS0] 83 bytes 2023-09-07 20:00:00 [NOTICE] mqtt_handle.c:244 read uuid:3388976e-6240-4abc-9956-932105f92a27, group:metG1_2, node:test 2023-09-07 20:00:00 [DEBUG] mqtt_client.c:515 recv [/neuron/mqtt/read/req, QoS0] 83 bytes 2023-09-07 20:00:00 [NOTICE] mqtt_handle.c:244 read uuid:2349d62e-8d52-4284-80a6-0c9d23b30cb2, group:metG2_2, node:test 2023-09-07 20:00:00 [NOTICE] mqtt_handle.c:244 read uuid:9abff23b-2ba2-445b-9d30-39b3375d5c61, group:metG2_1, node:test 2023-09-07 20:00:00 [DEBUG] mqtt_client.c:515 recv [/neuron/mqtt/read/req, QoS0] 91 bytes 2023-09-07 20:00:00 [NOTICE] mqtt_handle.c:244 read uuid:f7e27e2e-49c0-4cb2-8144-b476edbb8bf9, group:metEStorage_1, node:test 2023-09-07 20:00:00 [DEBUG] mqtt_client.c:515 recv [/neuron/mqtt/read/req, QoS0] 91 bytes 2023-09-07 20:00:00 [NOTICE] mqtt_handle.c:244 read uuid:be656de3-8518-49bb-9ba5-9966b1d1b593, group:metEStorage_2, node:test 2023-09-07 20:00:00 [DEBUG] mqtt_client.c:253 pub [/neuron/mqtt/bms/rack6_3, QoS0] 8693 bytes 2023-09-07 20:00:00 [DEBUG] mqtt_client.c:253 pub [/neuron/mqtt/read/resp, QoS0] 649 bytes 2023-09-07 20:00:04 [NOTICE] mqtt_plugin.c:63 initialize plugin MQTT success 2023-09-07 20:00:04 [NOTICE] mqtt_config.c:80 setting ssl disabled 2023-09-07 20:00:04 [NOTICE] mqtt_config.c:362 config client-id : neuron 2023-09-07 20:00:04 [NOTICE] mqtt_config.c:363 config qos : 0 2023-09-07 20:00:04 [NOTICE] mqtt_config.c:364 config format : format-values 2023-09-07 20:00:04 [NOTICE] mqtt_config.c:366 config write-req-topic : /neuron/mqtt/write/req 2023-09-07 20:00:04 [NOTICE] mqtt_config.c:367 config write-resp-topic: /neuron/mqtt/write/resp 2023-09-07 20:00:04 [NOTICE] mqtt_config.c:369 config cache : 0 2023-09-07 20:00:04 [NOTICE] mqtt_config.c:370 config cache-mem-size : 0 2023-09-07 20:00:04 [NOTICE] mqtt_config.c:371 config cache-disk-size : 0 2023-09-07 20:00:04 [NOTICE] mqtt_config.c:373 config cache-sync-interval : 100 2023-09-07 20:00:04 [NOTICE] mqtt_config.c:375 config host : 127.0.0.1 2023-09-07 20:00:04 [NOTICE] mqtt_config.c:376 config port : 1883 2023-09-07 20:00:04 [NOTICE] mqtt_config.c:379 config username : admin 2023-09-07 20:00:04 [NOTICE] mqtt_config.c:382 config password : **** 2023-09-07 20:00:04 [NOTICE] mqtt_config.c:386 config ssl : 0 2023-09-07 20:00:04 [DEBUG] mqtt_client.c:1094 cache disabled 2023-09-07 20:00:04 [DEBUG] mqtt_client.c:1022 tls disabled 2023-09-07 20:00:04 [NOTICE] mqtt_plugin.c:283 config plugin MQTT success 2023-09-07 20:00:04 [NOTICE] mqtt_plugin.c:313 start plugin MQTT success 2023-09-07 20:00:04 [NOTICE] mqtt_client.c:435 mqtt client connected 2023-09-07 20:00:04 [NOTICE] mqtt_plugin.c:33 plugin MQTT connected

2023-09-07 19:00:00 [DEBUG] mqtt_client.c:253 pub [/neuron/mqtt/test/metG2_1, QoS0] 602 bytes 2023-09-07 19:00:00 [DEBUG] mqtt_client.c:515 recv [/neuron/mqtt/read/req, QoS0] 83 bytes 2023-09-07 19:00:00 [NOTICE] mqtt_handle.c:244 read uuid:962e78bf-29ba-4962-9a4b-9c87b5b19c1f, group:metG1_1, node:test 2023-09-07 19:00:00 [DEBUG] mqtt_client.c:515 recv [/neuron/mqtt/read/req, QoS0] 83 bytes 2023-09-07 19:00:00 [DEBUG] mqtt_client.c:253 pub [/neuron/mqtt/test/metG2_2, QoS0] 206 bytes 2023-09-07 19:00:00 [NOTICE] mqtt_handle.c:244 read uuid:8fd93c09-58d8-4112-bce0-f57590d561f2, group:metG1_2, node:test 2023-09-07 19:00:00 [DEBUG] mqtt_client.c:515 recv [/neuron/mqtt/read/req, QoS0] 83 bytes 2023-09-07 19:00:00 [NOTICE] mqtt_handle.c:244 read uuid:b56dba6c-8dd9-40d0-8705-1175ee67732e, group:metG2_1, node:test 2023-09-07 19:00:00 [DEBUG] mqtt_client.c:515 recv [/neuron/mqtt/read/req, QoS0] 83 bytes 2023-09-07 19:00:00 [DEBUG] mqtt_client.c:515 recv [/neuron/mqtt/read/req, QoS0] 91 bytes 2023-09-07 19:00:00 [DEBUG] mqtt_client.c:515 recv [/neuron/mqtt/read/req, QoS0] 91 bytes 2023-09-07 19:00:00 [NOTICE] mqtt_handle.c:244 read uuid:07800cb6-ef80-425a-925d-09b674b585ff, group:metEStorage_1, node:test 2023-09-07 19:00:00 [NOTICE] mqtt_handle.c:244 read uuid:fba762ad-0e9e-495c-be86-7d71a2e3ae25, group:metG2_2, node:test 2023-09-07 19:00:00 [NOTICE] mqtt_handle.c:244 read uuid:81282de8-d376-457a-a5fc-f59bc79d5518, group:metEStorage_2, node:test 2023-09-07 19:00:00 [DEBUG] mqtt_client.c:253 pub [/neuron/mqtt/t2/r1_1, QoS0] 1280 bytes 2023-09-07 19:00:00 [DEBUG] mqtt_client.c:253 pub [/neuron/mqtt/test/pcs_1, QoS0] 366 bytes 2023-09-07 19:00:00 [DEBUG] mqtt_client.c:253 pub [/neuron/mqtt/t2/r4_1, QoS0] 1280 bytes 2023-09-07 19:00:00 [DEBUG] mqtt_client.c:253 pub [/neuron/mqtt/t2/r1_2, QoS0] 612 bytes 2023-09-07 19:00:00 [DEBUG] mqtt_client.c:253 pub [/neuron/mqtt/t2/r4_2, QoS0] 609 bytes 2023-09-07 19:00:00 [DEBUG] mqtt_client.c:253 pub [/neuron/mqtt/t2/r3_1, QoS0] 1280 bytes 2023-09-07 19:00:00 [DEBUG] mqtt_client.c:253 pub [/neuron/mqtt/test/pcs_2, QoS0] 859 bytes 2023-09-07 19:00:00 [NOTICE] mqtt_handle.c:589 handle read response,{"node": "test", "group": "metG1_1", "timestamp": 1694113200221, "uuid": "962e78bf-29ba-4962-9a4b-9c87b5b19c1f", "values": {"P_A_V": 230.5}, "errors": {}, "metas": {}} 2023-09-07 19:00:00 [DEBUG] mqtt_client.c:253 pub [/neuron/mqtt/read/resp, QoS0] 167 bytes 2023-09-07 19:00:00 [DEBUG] mqtt_client.c:253 pub [/neuron/mqtt/test/pcs_3, QoS0] 871 bytes 2023-09-07 19:00:00 [NOTICE] mqtt_handle.c:589 handle read response,{"node": "test", "group": "metG1_2", "timestamp": 1694113200231, "uuid": "8fd93c09-58d8-4112-bce0-f57590d561f2", "values": {"P_F": 938676.0}, "errors": {}, "metas": {}} 2023-09-07 19:00:00 [DEBUG] mqtt_client.c:253 pub [/neuron/mqtt/read/resp, QoS0] 168 bytes 2023-09-07 19:00:00 [NOTICE] mqtt_handle.c:589 handle read response,{"node": "test", "group": "metG2_1", "timestamp": 1694113200251, "uuid": "b56dba6c-8dd9-40d0-8705-1175ee67732e", "values": {"P_A_V": 230.3}, "errors": {}, "metas": {}} 2023-09-07 19:00:00 [DEBUG] mqtt_client.c:253 pub [/neuron/mqtt/read/resp, QoS0] 167 bytes 2023-09-07 19:00:00 [NOTICE] mqtt_handle.c:589 handle read response,{"node": "test", "group": "metEStorage_1", "timestamp": 1694113200251, "uuid": "07800cb6-ef80-425a-925d-09b674b585ff", "values": {"P_A_V"}, "errors": {}, "metas": {}} 2023-09-07 19:00:00 [DEBUG] mqtt_client.c:253 pub [/neuron/mqtt/read/resp, QoS0] 166 bytes 2023-09-07 19:00:04 [NOTICE] mqtt_plugin.c:63 initialize plugin MQTT success 2023-09-07 19:00:04 [NOTICE] mqtt_config.c:80 setting ssl disabled 2023-09-07 19:00:04 [NOTICE] mqtt_config.c:362 config client-id : neuron 2023-09-07 19:00:04 [NOTICE] mqtt_config.c:363 config qos : 0 2023-09-07 19:00:04 [NOTICE] mqtt_config.c:364 config format : format-values 2023-09-07 19:00:04 [NOTICE] mqtt_config.c:366 config write-req-topic : /neuron/mqtt/write/req 2023-09-07 19:00:04 [NOTICE] mqtt_config.c:367 config write-resp-topic: /neuron/mqtt/write/resp 2023-09-07 19:00:04 [NOTICE] mqtt_config.c:369 config cache : 0 2023-09-07 19:00:04 [NOTICE] mqtt_config.c:370 config cache-mem-size : 0 2023-09-07 19:00:04 [NOTICE] mqtt_config.c:371 config cache-disk-size : 0 2023-09-07 19:00:04 [NOTICE] mqtt_config.c:373 config cache-sync-interval : 100 2023-09-07 19:00:04 [NOTICE] mqtt_config.c:375 config host : 127.0.0.1 2023-09-07 19:00:04 [NOTICE] mqtt_config.c:376 config port : 1883 2023-09-07 19:00:04 [NOTICE] mqtt_config.c:379 config username : admin 2023-09-07 19:00:04 [NOTICE] mqtt_config.c:382 config password : **** 2023-09-07 19:00:04 [NOTICE] mqtt_config.c:386 config ssl : 0 2023-09-07 19:00:04 [DEBUG] mqtt_client.c:1094 cache disabled 2023-09-07 19:00:04 [DEBUG] mqtt_client.c:1022 tls disabled 2023-09-07 19:00:04 [NOTICE] mqtt_plugin.c:283 config plugin MQTT success 2023-09-07 19:00:04 [NOTICE] mqtt_plugin.c:313 start plugin MQTT success

2023-09-08 05:00:00 [INFO] manager.c:240 manager recv msg from: ems to , type: NEU_REQRESP_TRANS_DATA 2023-09-08 05:00:00 [INFO] manager.c:1174 forward msg to pipe 1146067420 2023-09-08 05:00:00 [DEBUG] manager.c:251 forward trans data to pipe: 1146067420 2023-09-08 05:00:00 [DEBUG] driver.c:1333 t2-r1_2 timer: 128 2023-09-08 05:00:02 [WARN] daemon.c:175 write /tmp/neuron.pid, error Success(0) 2023-09-08 05:00:02 [INFO] persist.c:210 query CREATE TABLE IF NOT EXISTS migrations ( migration_id INTEGER PRIMARY KEY, version TEXT NOT NULL UNIQUE, description TEXT NOT NULL, dirty INTEGER NOT NULL, created_at TEXT NOT NULL DEFAULT CURRENT_TIMESTAMP) success 2023-09-08 05:00:02 [NOTICE] persist.c:448 schema head version=0042 2023-09-08 05:00:02 [NOTICE] main.c:74 neuron start, daemon: 0, version: 2.6.0-dev (d4e9e63 2023-09-08) 2023-09-08 05:00:02 [NOTICE] event_linux.c:255 add io, fd: 11, epoll: 8, ret: 0 2023-09-08 05:00:02 [NOTICE] rest.c:57 bind url: http://0.0.0.0:7000 2023-09-08 05:00:02 [INFO] http_handler.c:86 http add handler, method: GET, url: /web, ret: 0 2023-09-08 05:00:02 [INFO] http_handler.c:86 http add handler, method: , url: /, ret: 0 2023-09-08 05:00:02 [INFO] http_handler.c:86 http add handler, method: POST, url: /api/v2/ping, ret: 0 2023-09-08 05:00:02 [INFO] http_handler.c:86 http add handler, method: POST, url: /api/v2/login, ret: 0 2023-09-08 05:00:02 [INFO] http_handler.c:86 http add handler, method: POST, url: /api/v2/password, ret: 0 2023-09-08 05:00:02 [INFO] http_handler.c:86 http add handler, method: POST, url: /api/v2/tags, ret: 0 2023-09-08 05:00:02 [INFO] http_handler.c:86 http add handler, method: PUT, url: /api/v2/tags, ret: 0 2023-09-08 05:00:02 [INFO] http_handler.c:86 http add handler, method: GET, url: /api/v2/tags, ret: 0 2023-09-08 05:00:02 [INFO] http_handler.c:86 http add handler, method: DELETE, url: /api/v2/tags, ret: 0 2023-09-08 05:00:02 [INFO] http_handler.c:86 http add handler, method: POST, url: /api/v2/group, ret: 0 2023-09-08 05:00:02 [INFO] http_handler.c:86 http add handler, method: PUT, url: /api/v2/group, ret: 0

eeff commented 1 year ago

Please provide the log from neuron.log with the timestamp matches the problem you specified. For example, around timestamp 2023-09-07 19:00:00.

Also, the version latest is not informative, please run neuron --version to provide this information.

jerryma0912 commented 1 year ago

Can you provide an email address? I will email the log to you version：Neuron 2.6.0-dev (d4e9e63)

eeff commented 1 year ago

Can you provide an email address? I will email the log to you version：Neuron 2.6.0-dev (d4e9e63)

Did you modify the code ? If so, I hardly can draw any conclusion without information about your changes.

jerryma0912 commented 1 year ago

Oh yes, your question inspired me!

I have modified one thing, that is, the response format of the read request. The modified response format is consistent with the actively reported attribute format. But I'm not sure what's wrong with what I modified, can you help me?

I referred to the generate_upload_json function. The modified content is as follows：

In the neu_json_mqtt.h: the following structure is added:

typedef struct {
     char* group;
     char* node;
     uint64_t timestamp;
     char * uuid;
} json_mqtt_unify_format_t;

In the neu_json_mqtt.c： the following function is added:

int json_encode_mqtt_unify_format_resp(void *json_object, void *param)
{
    int                       ret  = 0;
    json_mqtt_unify_format_t *resp = (json_mqtt_unify_format_t *) param;
    neu_json_elem_t resp_elems[] = { {
                                     .name      = "node",
                                     .t         = NEU_JSON_STR,
                                     .v.val_str = resp->node,
                                 },
                                 {
                                     .name      = "group",
                                     .t         = NEU_JSON_STR,
                                     .v.val_str = resp->group,
                                 },
                                 {
                                     .name      = "timestamp",
                                     .t         = NEU_JSON_INT,
                                     .v.val_int = resp->timestamp,
                                 },
                                 {
                                     .name      = "uuid",
                                     .t         = NEU_JSON_STR,
                                     .v.val_str = resp->uuid,
                                 }  };
    ret = neu_json_encode_field(json_object, resp_elems,NEU_JSON_ELEM_SIZE(resp_elems));

    return ret;
}

In the mqtt_handle.c: the generate_read_resp_json function has been modified:

static char *generate_read_resp_json(neu_plugin_t *         plugin,
                                     neu_json_mqtt_t *      mqtt,
                                     neu_resp_read_group_t *data)
{
    neu_resp_tag_value_meta_t *tags     = data->tags;
    uint16_t                   len      = data->n_tag;
    char *                     json_str = NULL;

   // ------the following has been added ------
    json_mqtt_unify_format_t header   = {
        .group     = (char *) data->group,
        .node      = (char *) data->driver,
        .timestamp = global_timestamp,
        .uuid      = (char *) mqtt->uuid};
  // -----------------end-----------------

    neu_json_read_resp_t       json     = { 0 };

    if (0 != tag_values_to_json(tags, len, &json)) {
        plog_error(plugin, "tag_values_to_json fail");
        return NULL;
    }

    // ----------- the following has been modified -----------
//    neu_json_encode_with_mqtt(&json, neu_json_encode_read_resp, mqtt,
//                              neu_json_encode_mqtt_resp, &json_str);
    neu_json_encode_with_mqtt(&json, neu_json_encode_read_resp1, &header,
                          json_encode_mqtt_unify_format_resp,
                          &json_str);

    for (int i = 0; i < json.n_tag; i++) {
        if (json.tags[i].n_meta > 0) {
            free(json.tags[i].metas);
        }
    }
    // ----------------------end-------------------

    if (json.tags) {
        free(json.tags);
    }
    return json_str;
}

eeff commented 1 year ago

I think as long as your code does not segfault, it does not relate to the problem reported. If you modify the code in neuron core, then probably it is not the mqtt plugin causing the problem.

jerryma0912 commented 1 year ago

I only modified this part of the code, the core code was not updated. So I still think that this issue has nothing to do with the content I modified.

jerryma0912 commented 1 year ago

I only modified this part of the code, the core code was not updated. So I still think that this issue has nothing to do with the content I modified.

I suggest use the official version to test this problem : )

emqx / neuron

The mqtt plugin will automatically exit and reload #1518