search

gennadiygnezdilov / ocpp-1.6J-example-request-response

Example requests and responses OCPP 1.6J
20 stars 2 forks source link

[QUESTION] My charger is disconnecting after my server respond an authorize response #2

Closed zekageri closed 3 months ago

zekageri commented 9 months ago

Hi!

I want to start a charging session with a node.js server and a mennekes charger.

Server sends a RemoteStartTransaction with a dummy data for now

RemoteStartTransaction

{
    connectorId: connectorID,
    idTag: dummyIDTag, 
}

Charger answers with an Authorize request

Authorize

{
  "idTag": "testIDTag"
}

Server responds with an accepted message

{
    status: "Accepted",
    "idTagInfo":{
        "status ":" Accepted"
    }
}

And the charger disconnects after that. Do you know what happens? Is my response malformed?

zekageri commented 9 months ago

My charger logs show the following messages

Jan 26 20:45:09 cp cp_app[953]: <43>             hmi__dev_manager.c:1344 [01cca000] (*I) - >>> setting device 'hmi mk_led (K)' from category 'HMI_STATE_MSG' to 'HMI_AUTHENTICATING' (reenter:0, conn_idx:0) 
Jan 26 20:45:09 cp cp_app[953]: <20>                authorization.c:984  [01cca000] (*D) - authorization_handle_idtag_event(): state:pending 
Jan 26 20:45:09 cp cp_app[953]: <41>                 websock_comm.c:2221 [01cca000] (*D) - websock_comm_send_message(): processing CONFIRMATION... 
Jan 26 20:45:09 cp cp_app[953]: <41>                  ocpp_msging.c:142  [01cca000] (  ) - OCPP RemoteStartTransaction.conf sent [3, "3cfd275c-2fec-4729-9ca4-f555abe4ea16", {"status": "Accepted"}] 
Jan 26 20:45:09 cp cp_app[953]: <41>                 websock_comm.c:497  [01cca000] (*D) - calling lws_write() with 67 bytes and content [3, "3cfd275c-2fec-4729-9ca4-f555abe4ea16", {"status": "Accepted"}] 
Jan 26 20:45:09 cp cp_app[953]: <41>                 websock_comm.c:497  [01cca000] (*D) - calling lws_write() with 52 bytes and content [2, "19772489", "Authorize", {"idTag": "testIDTag"}] 
Jan 26 20:45:09 cp cp_app[953]: <06>                   statistics.c:48   [01cca000] (*I) - MK_PIC24 statistics - RX: 1245 (5.448 kB), TX: 670 (2.246 kB), CRC16 errors: 0, non-recoverable comm errors: 0 
Jan 26 20:45:09 cp cp_app[953]: <06>                   statistics.c:59   [01cca000] (*I) - Timer Pool statistics - active: 13, max. concurrent: 17, total: 584, cb calls: 2905, premature events: 0, pool exhausted: 0, event_new() fails: 0, event_add() fails: 0 
Jan 26 20:45:09 cp cp_app[953]: <41>                 websock_comm.c:618  [01cca000] (*D) - send_from_req_buffer: not sending, 1 requests still pending 
Jan 26 20:45:09 cp cp_app[953]: <41>                 websock_comm.c:618  [01cca000] (*D) - send_from_req_buffer: not sending, 1 requests still pending 
Jan 26 20:45:09 cp cp_app[953]: <41>                 websock_comm.c:1024 [01cca000] (*D) - callback_ocpp(): (LWS_CALLBACK_CLIENT_RECEIVE) len:52 
Jan 26 20:45:09 cp cp_app[953]: <41>                 websock_comm.c:909  [01cca000] (*D) - websocket_msg_received len:52 = '[3,"19772489",{"idTagInfo":{"status ":" Accepted"}}]' 
Jan 26 20:45:09 cp cp_app[953]: <41>                  ocpp_msging.c:134  [01cca000] (  ) - OCPP Authorize.conf received [3,"19772489",{"idTagInfo":{"status ":" Accepted"}}] 
Jan 26 20:45:09 cp cp_app[953]: <41>     json_authorize_converter.c:83   [01cca000] (*D) - converter_authorize_response_json_to_asn1_16():  
Jan 26 20:45:09 cp cp_app[953]: <41>     json_authorize_converter.c:144  [01cca000] (*E) - converter_authorize_response_json_to_asn1_16(): OCPP JSON parse_error 
Jan 26 20:45:09 cp cp_app[953]: <41>                 websock_comm.c:819  [01cca000] (*E) - websocket_msg_received(): RESPONSE parsing error 
Jan 26 20:45:10 cp cp_app[953]: <06>                  temperature.c:913  [01cca000] (*I) - Temperatures: CPU: +52.0°C RFID: +30.5°C AUX: +45.0°C 
Jan 26 20:45:10 cp cp_app[953]: <41>                  ocpp_client.c:850  [01cca000] (*I) - heartbeat_timer_cb(): sending heartbeat 
Jan 26 20:45:10 cp cp_app[953]: <41>                  ocpp_client.c:548  [01cca000] (*I) - send_heartbeat():  
Jan 26 20:45:10 cp cp_app[953]: <41>                  ocpp_client.c:1513 [01cca000] (*I) - send_request_to_backend(): (OCPP Heartbeat mode:queued volatile not transaction relevant) 
Jan 26 20:45:10 cp cp_app[953]: <41>                  ocpp_msging.c:130  [01cca000] (  ) - OCPP Heartbeat.req sent [2, "118918417", "Heartbeat", {}] 
Jan 26 20:45:10 cp cp_app[953]: <41>                 websock_comm.c:497  [01cca000] (*D) - calling lws_write() with 33 bytes and content [2, "118918417", "Heartbeat", {}] 
Jan 26 20:45:10 cp cp_app[953]: <41>                 websock_comm.c:618  [01cca000] (*D) - send_from_req_buffer: not sending, 1 requests still pending 
Jan 26 20:45:11 cp cp_app[953]: <41>                 websock_comm.c:618  [01cca000] (*D) - send_from_req_buffer: not sending, 1 requests still pending 
Jan 26 20:45:11 cp cp_app[953]: <41>                 websock_comm.c:1024 [01cca000] (*D) - callback_ocpp(): (LWS_CALLBACK_CLIENT_RECEIVE) len:78 
Jan 26 20:45:11 cp cp_app[953]: <41>                 websock_comm.c:909  [01cca000] (*D) - websocket_msg_received len:78 = '[3,"118918417",{"status":"Accepted","currentTime":"2024-01-26T20:45:11.374Z"}]' 
Jan 26 20:45:11 cp cp_app[953]: <41>                  ocpp_msging.c:134  [01cca000] (  ) - OCPP Heartbeat.conf received [3,"118918417",{"status":"Accepted","currentTime":"2024-01-26T20:45:11.374Z"}] 
Jan 26 20:45:11 cp cp_app[953]: <41>     json_heartbeat_converter.c:74   [01cca000] (*D) - converter_heartbeat_response_json_to_asn1_16():  
Jan 26 20:45:11 cp cp_app[953]: <41>                    json_comm.c:624  [01cca000] (*D) - json_comm_parse_ts(): failed to parse datetime '2024-01-26T20:45:11.374Z', retrying with '2024-01-26T20:45:11Z' 
Jan 26 20:45:11 cp cp_app[953]: <41>                    json_comm.c:627  [01cca000] (*D) - json_comm_parse_ts(): successfully parsed fixed datetime '2024-01-26T20:45:11Z' 
Jan 26 20:45:11 cp cp_app[953]: <41>                 websock_comm.c:811  [01cca000] (*D) - websocket_msg_received(): successfully parsed RESPONSE, notifying... 
Jan 26 20:45:11 cp cp_app[953]: <41>                     response.c:289  [01cca000] (*I) - backend_heartbeat_response(): Time since epoch: 1706301911 
Jan 26 20:45:11 cp cp_app[953]: <17>                     sysclock.c:270  [01cca000] (*I) - sysclock_set_time(): System booted at Fri, 26 Jan 20:25:39 2024 
Jan 26 20:45:11 cp cp_app[953]: <17>                     sysclock.c:273  [01cca000] (*I) - sysclock_set_time(): System clock drifted by 0 seconds (new time - system time) 
Jan 26 20:45:14 cp cp_app[953]: <20>                authorization.c:322  [01cca000] (*I) - authorization_timeout_cb():  
Jan 26 20:45:14 cp cp_app[953]: <20>                authorization.c:324  [01cca000] (  ) - OCPP Authorize.conf timeout 
Jan 26 20:45:14 cp cp_app[953]: <20>                authorization.c:1056 [01cca000] (*E) - authorization_is_authorization_pending(): Authorization is pending but authorization timer is not running 
Jan 26 20:45:14 cp cp_app[953]: <43>             hmi__dev_manager.c:1344 [01cca000] (*I) - >>> setting device 'hmi log' from category 'HMI_STATE_MSG' to 'HMI_IDLE' (reenter:0, conn_idx:0) 
Jan 26 20:45:14 cp cp_app[953]: <43>                      hmi_log.c:182  [01cca000] (  ) - User interface: Available 
Jan 26 20:45:14 cp cp_app[953]: <43>             hmi__dev_manager.c:1344 [01cca000] (*I) - >>> setting device 'hmi mk_led (K)' from category 'HMI_STATE_MSG' to 'HMI_IDLE' (reenter:0, conn_idx:0) 
Jan 26 20:45:14 cp cp_app[953]: <41>                  ocpp_client.c:900  [01cca000] (*I) - message_wait_for_response_timeout_cb(): 0x1d87dd8 
Jan 26 20:45:14 cp cp_app[953]: <41>                  ocpp_msging.c:247  [01cca000] (WW) - Confirmation for OCPP Authorize.req [19772489] timeout 
Jan 26 20:45:14 cp cp_app[953]: <41>                  ocpp_msging.c:251  [01cca000] (*W) - ocpp_msging_log_message_timeout_to_user(): Confirmation for OCPP Authorize.req [19772489] timeout 
Jan 26 20:45:14 cp cp_app[953]: <41>                   tcpip_comm.c:1246 [01cca000] (*D) - tcpip_comm_get_watchdog_remaining_time():  
Jan 26 20:45:14 cp cp_app[953]: <41>                   tcpip_comm.c:1252 [01cca000] (*D) - tcpip_comm_get_watchdog_remaining_time(): Remaining time: 10236 sec 
Jan 26 20:45:14 cp cp_app[953]: <41>                   tcpip_comm.c:1597 [01cca000] (*I) - tcpip_comm_manage_generic_error(): Connected 
Jan 26 20:45:14 cp cp_app[953]: <41>                   tcpip_comm.c:1601 [01cca000] (*D) - tcpip_comm_manage_generic_error(): System will reboot in 0:02:50:36 (d:h:m:s) if still offline 
Jan 26 20:45:14 cp cp_app[953]: <41>                   tcpip_comm.c:1609 [01cca000] (  ) - Disconnected from backend
Jan 26 20:45:14 cp cp_app[953]: <41>                   tcpip_comm.c:1707 [01cca000] (*I) - tcpip_comm_notify_disconnected(): Connected, 10800 
Jan 26 20:45:14 cp cp_app[953]: <41>                 websock_comm.c:1840 [01cca000] (*D) - websock_comm_uninit():  
Jan 26 20:45:14 cp cp_app[953]: <41>                 websock_comm.c:1857 [01cca000] (*D) - websock_comm_uninit(): destroying context 
Jan 26 20:45:14 cp cp_app[953]: <41>                 websock_comm.c:1024 [01cca000] (*D) - callback_ocpp(): (LWS_CALLBACK_CLOSED) len:0 
Jan 26 20:45:14 cp cp_app[953]: <41>                   tcpip_comm.c:1496 [01cca000] (*I) - tcpip_comm_notify_ws_error_description(): Closed connection 
Jan 26 20:45:14 cp cp_app[953]: <41>                 websock_comm.c:1024 [01cca000] (*D) - callback_ocpp(): (LWS_CALLBACK_WSI_DESTROY) len:0 
Jan 26 20:45:14 cp cp_app[953]: <41>                 websock_comm.c:1024 [01cca000] (*D) - callback_ocpp(): (LWS_CALLBACK_PROTOCOL_DESTROY) len:0 
Jan 26 20:45:14 cp cp_app[953]: <41>                 websock_comm.c:2603 [01cca000] (*D) - clear_send_buffers():  
Jan 26 20:45:14 cp cp_app[953]: <41>                  ocpp_client.c:3127 [01cca000] (*D) - ocpp_client_disable_connection():  
Jan 26 20:45:14 cp cp_app[953]: <20>               ocpp_connector.c:3078 [01cca000] (*D) - ocpp_connector_handle_offline():  
Jan 26 20:45:14 cp cp_app[953]: <41>                   tcpip_comm.c:1431 [01cca000] (*I) - tcp_get_connection_timeout(): timeout:196  
Jan 26 20:45:14 cp cp_app[953]: <41>                   tcpip_comm.c:1633 [01cca000] (*I) - tcpip_comm_manage_generic_error(): reconnect in 196 seconds 
Jan 26 20:45:14 cp cp_app[953]: <41>                   tcpip_comm.c:416  [01cca000] (*I) - tcp_increase_connection_timeout(): timeout:342 | random:50  
Jan 26 20:45:18 cp cp_app[953]: <41>                   tcpip_comm.c:2246 [01cca000] (*D) - tcpip_comm_get_connection_state_str(): boot pending timeout '192' 
Jan 26 20:45:23 cp cp_app[953]: <41>                   tcpip_comm.c:2246 [01cca000] (*D) - tcpip_comm_get_connection_state_str(): boot pending timeout '187' 
Jan 26 20:45:25 cp cp_app[953]: <21>          modem_state_monitor.c:200  [01cca000] (*I) - URC: +CREG?^M (Registration status) 
Jan 26 20:45:28 cp cp_app[953]: <41>                   tcpip_comm.c:2246 [01cca000] (*D) - tcpip_comm_get_connection_state_str(): boot pending timeout '182' 
Jan 26 20:45:32 cp cp_app[953]: <41>                datalink_comm.c:136  [01cca000] (*D) - Rx: 112026 bytes 
Jan 26 20:45:32 cp cp_app[953]: <41>                datalink_comm.c:171  [01cca000] (*D) - Tx: 102600 bytes 
Jan 26 20:45:32 cp cp_app[953]: <41>                datalink_comm.c:229  [01cca000] (*D) - Data consumption: txrx:214626, diff:8252, current month:12842599 bytes