Fraunhofer-FIT-DIEN / iec104-python

A Python module to simulate SCADA and RTU communication over protocol 60870-5-104 to research ICT behavior in power grids.
https://iec104-python.readthedocs.io/latest/python/index.html
GNU General Public License v3.0
50 stars 9 forks source link

c104 Type does not match with client request #20

Closed iblasi closed 4 months ago

iblasi commented 6 months ago

I am trying to launch a server and a client at the same time. The exchange of data is a M_ME_NC_1 (Measured value, short floating point number). I used Wireshark to see the exchanged packages and I see that there is a C_RD_NA_1 (Read Command) that makes the point read to fail. The client code I used:

import c104
client = c104.Client(tick_rate_ms=1000, command_timeout_ms=1000)
connection = client.add_connection(ip="127.0.0.1", port=2404, init=c104.Init.INTERROGATION)
station = connection.add_station(common_address=4)
point01 = station.add_point(io_address=20053, type=c104.Type.M_ME_NC_1)
client.start()
if point01.read():
   print(f"-> SUCCESS {point01.value}")
else:
   print("-> FAILURE")

The Wireshark shows that during the request there is the package with the command mentioned: simple_wireshark_remote

And for that reason it seems to fail the read of the point value:

[c104.Client] Created
[c104.Client] add_connection] IP 127.0.0.1 | PORT 2404
[c104.Connection] Created
[c104.Connection] add_station] CA 4
[c104.Connection] state] CLOSED -> CLOSED_AWAIT_OPEN
[c104.Connection] connect] Asynchronous connect to 127.0.0.1:2404
[c104.Client] start] Started
[c104.Connection] set_open] 127.0.0.1:2404
[c104.Connection] set_open] Opening connection to 127.0.0.1:2404
[c104.Connection] state] CLOSED_AWAIT_OPEN -> OPEN_MUTED
[c104.Connection] set_open] Unmuting connection to 127.0.0.1:2404
[c104.Connection] unmute] Unmute connection to 127.0.0.1:2404
[c104.Connection] raw_message_handler] Stats | TOTAL 0 �s
[c104.Connection] set_open] DONE 127.0.0.1:2404
[c104.Connection] connection_handler] Connection OPENED to 127.0.0.1:2404 | TOTAL 92 �s
[c104.Connection] raw_message_handler] Stats | TOTAL 8 �s
[c104.Connection] set_muted] Muted: 0 for connection to 127.0.0.1:2404
[c104.Connection] state] OPEN_MUTED -> OPEN_AWAIT_INTERROGATION
[c104.Connection] connection_handler] Connection ACTIVATED to 127.0.0.1:2404 | TOTAL 17 �s
[c104.Connection] raw_message_handler] Stats | TOTAL 1 �s
[c104.Client] thread_run] Connected servers: 1
[c104.Connection] raw_message_handler] Stats | TOTAL 0 �s
[c104.Connection] await_command_success] Await 4-C_RD_NA_1-20053
[c104.Connection] raw_message_handler] Stats | TOTAL 9 �s
[c104.Connection] state] OPEN_AWAIT_INTERROGATION -> OPEN
[c104.Connection] set_command_success] Result 65535-C_IC_NA_1-0: 1
[c104.Connection] asdu_handler] C_IC_NA_1 Response Stats | CA 65535 | IOA 0 | TOTAL 27 �s
[c104.Connection] raw_message_handler] Stats | TOTAL 12 �s
[c104.Connection] set_command_success] Result 65535-C_IC_NA_1-0: 1
[c104.Connection] asdu_handler] C_IC_NA_1 Response Stats | CA 65535 | IOA 0 | TOTAL 23 �s
[c104.Client] thread_run] Active servers: 1
[c104.Connection] await_command_success] Timeout 4-C_RD_NA_1-20053
[c104.Connection] await_command_success] Stats 4-C_RD_NA_1-20053 | TOTAL 18446744073709440 �s
-> FAILURE
[c104.Connection] raw_message_handler] Stats | TOTAL 7 �s
[c104.Connection] set_closed] Connection closed to 127.0.0.1:2404
[c104.Connection] state] OPEN -> CLOSED_AWAIT_RECONNECT
[c104.Connection] connection_handler] Connection CLOSED to 127.0.0.1:2404 | TOTAL 40 �s
[c104.Connection] state] CLOSED_AWAIT_RECONNECT -> CLOSED
[c104.Client] stop] Stopped
[c104.Client] Removed
[c104.Connection] Removed

If I try it making my local server, I see the command C_RD_NA_1, but does not fail. Can I configure any other parameter o could be a problem from the server from the third party? It seems that the third party server has no problem with other connections from other users.

However, as mentioned, when I create my local server with the code from the example (changing the common_address=47 and io_address=11 similar to the example of documentation), I correctly access the data:

[c104.Client] Created
[c104.Client] add_connection] IP 127.0.0.1 | PORT 2404
[c104.Connection] Created
[c104.Connection] add_station] CA 47
[c104.Connection] state] CLOSED -> CLOSED_AWAIT_OPEN
[c104.Connection] connect] Asynchronous connect to 127.0.0.1:2404
[c104.Client] start] Started
Waiting for connection to 127.0.0.1:2404
[c104.Connection] set_open] 127.0.0.1:2404
[c104.Connection] set_open] Opening connection to 127.0.0.1:2404
[c104.Connection] state] CLOSED_AWAIT_OPEN -> OPEN_MUTED
[c104.Connection] set_open] Unmuting connection to 127.0.0.1:2404
[c104.Connection] unmute] Unmute connection to 127.0.0.1:2404
[c104.Connection] raw_message_handler] Stats | TOTAL 0 �s
[c104.Connection] set_open] DONE 127.0.0.1:2404
[c104.Connection] connection_handler] Connection OPENED to 127.0.0.1:2404 | TOTAL 77 �s
[c104.Connection] raw_message_handler] Stats | TOTAL 3 �s
[c104.Connection] set_muted] Muted: 0 for connection to 127.0.0.1:2404
[c104.Connection] state] OPEN_MUTED -> OPEN_AWAIT_INTERROGATION
[c104.Connection] connection_handler] Connection ACTIVATED to 127.0.0.1:2404 | TOTAL 13 �s
[c104.Connection] raw_message_handler] Stats | TOTAL 16 �s
[c104.Connection] asdu_handler] M_ME_NC_1 Report Stats | CA 47 | IOA 11 | TOTAL 35 �s
[c104.Connection] raw_message_handler] Stats | TOTAL 1 �s
[c104.Client] thread_run] Connected servers: 1
[c104.Connection] raw_message_handler] Stats | TOTAL 5 �s
[c104.Connection] state] OPEN_AWAIT_INTERROGATION -> OPEN
[c104.Connection] set_command_success] Result 47-C_IC_NA_1-0: 1
[c104.Connection] asdu_handler] C_IC_NA_1 Response Stats | CA 47 | IOA 0 | TOTAL 25 �s
[c104.Connection] raw_message_handler] Stats | TOTAL 5 �s
[c104.Connection] asdu_handler] M_ME_NC_1 Report Stats | CA 47 | IOA 11 | TOTAL 13 �s
[c104.Connection] raw_message_handler] Stats | TOTAL 1 �s
[c104.Connection] set_command_success] Result 47-C_IC_NA_1-0: 1
[c104.Connection] asdu_handler] C_IC_NA_1 Response Stats | CA 47 | IOA 0 | TOTAL 13 �s
[c104.Connection] raw_message_handler] Stats | TOTAL 0 �s
[c104.Connection] await_command_success] Await 47-C_RD_NA_1-11
[c104.Connection] raw_message_handler] Stats | TOTAL 4 �s
[c104.Connection] set_command_success] Result 47-C_RD_NA_1-11: 1
[c104.Connection] asdu_handler] M_ME_NC_1 Report Stats | CA 47 | IOA 11 | TOTAL 32 �s
[c104.Connection] await_command_success] Result 47-C_RD_NA_1-11: 1
[c104.Connection] await_command_success] Stats 47-C_RD_NA_1-11 | TOTAL 999497 �s
-> SUCCESS 44.627750396728516
[c104.Connection] raw_message_handler] Stats | TOTAL 7 �s
[c104.Connection] set_closed] Connection closed to 127.0.0.1:2404
[c104.Connection] state] OPEN -> CLOSED_AWAIT_RECONNECT
[c104.Connection] connection_handler] Connection CLOSED to 127.0.0.1:2404 | TOTAL 43 �s
[c104.Connection] state] CLOSED_AWAIT_RECONNECT -> CLOSED
[c104.Client] stop] Stopped
[c104.Client] Removed
[c104.Connection] Removed
iblasi commented 6 months ago

From what I have been guessing it seems that although I define the common_address to 4 [c104.Connection] add_station] CA 47 during the client start, it changes to 65535 on the set_command_success and for that reason the ASDU, instead of 4 Wireshark shows that the ASDU is changed to 65535

[c104.Connection] set_command_success] Result 65535-C_IC_NA_1-0: 1
[c104.Connection] asdu_handler] C_IC_NA_1 Response Stats | CA 65535 | IOA 0 | TOTAL 27 �s
[c104.Connection] raw_message_handler] Stats | TOTAL 12 �s
[c104.Connection] set_command_success] Result 65535-C_IC_NA_1-0: 1
[c104.Connection] asdu_handler] C_IC_NA_1 Response Stats | CA 65535 | IOA 0 | TOTAL 23 �s

imagen

But I don't know why it changes it, if it due to a response of the server, and if I can set any parameter to avoid this. In my code I show the parameter client.connections[0].stations[0].common_address before the point.read() and it is 4, but internally it doesn't use it correctly as it can be seen in Wireshark log.

m-unkel commented 6 months ago

Hey, thanks for your feedback. The default behavior of the client is to send an interrogation and clock sync command once the connection is established.

Therefore your read command is "too early" and times out because the interrogation is not finished.

You can configure the initiation sequence in the client.add_connection() method via the init argument. For instance disable the init command via c104.Init.NONE

add_connection

Another option would be to increase the command timeout in the client constructor, but I would recommend the first option.

m-unkel commented 6 months ago

The init interrogation is send to common address 65535 (any), that is what you see in Wireshark. The read command should use your configured common address.

iblasi commented 6 months ago

Thank you for your explanation as it is very clear. Based on that I changed the add_connection and also add some sleeps and some prints to check all the information:

def main():
    # client, connection and station preparation
    client = c104.Client(tick_rate_ms=1000, command_timeout_ms=1000)
    #connection = client.add_connection(ip="127.0.0.1", port=2404, init=c104.Init.INTERROGATION)
    connection = client.add_connection(ip="127.0.0.1", port=2404, init=c104.Init.NONE)
    station = connection.add_station(common_address=4)

    # monitoring point preparation
    point = station.add_point(io_address=20053, type=c104.Type.M_ME_NC_1)

    # start
    time.sleep(1)
    client.start()

    time.sleep(3)
    while not connection.is_connected:
        print("Waiting for connection to {0}:{1}".format(connection.ip, connection.port))
        time.sleep(1)

    for i,c in enumerate(client.connections):
        print(f"Client:")
        print(f"        ip: {c.ip}")
        print(f"        port: {c.port}")
        print(f"        OriginatorAddress: {c.originator_address}")
        print(f"        Connected: {c.is_connected}")
        print(f"        Muted: {connection.is_muted}")
        print(f"        Stations: {len(c.stations)}")
        for j,s in enumerate(c.stations):
            print(f"                  CommonAddress: {s.common_address}")
            print(f"                  Has Points: {s.has_points}")
            print(f"                  Points: {len(s.points)}")
            for k,p in enumerate(s.points):
                print(f"                         IO address: {p.io_address} - Type: {p.type} - Command mode: {p.command_mode}")

    time.sleep(3)

    print("read")
    if point.read():
        print(f"-> SUCCESS {point.value}")
    else:
        print("-> FAILURE")
    print("exit")

In fact I also changed the timeout ms just in case, but the result is always the same: FAILURE Although the ASDU keeps correctly to 4 as common_address as you mentioned. But it seem to achieve timeout imagen

The Wireshark however seems to make less communications before exit, but I have no skills to understand what it is happening at this level. imagen

Can I check somehow the issue through any other way than the default debug?

m-unkel commented 6 months ago

I think the client is fine, bin the server is just not responding. Can you show me the servers code and it's debug log please? There should be two response packages in Wireshark within milliseconds, that are missing. One read command acknowledgement and the actual point value.

m-unkel commented 4 months ago

We have reviewed your submission and attempted to gather more information to assist you effectively. However, we have not received any further response or updates from your side.

To ensure that the issue tracker remains clean and manageable, we are closing this issue due to inactivity. If you still encounter this problem or have additional details to provide, please feel free to reopen this issue or create a new one. We are here to help and will be happy to assist you further.

Thank you for your understanding and cooperation.