libplctag / libplctag.NET

A .NET wrapper for libplctag.
https://libplctag.github.io/
Mozilla Public License 2.0
214 stars 53 forks source link

Modbus TCP Async Timeout #304

Closed nc-koko closed 1 year ago

nc-koko commented 1 year ago

Hello all,

I am trying to connect to and read from a Modbus TCP PLC tag and I keep getting timeouts when using the async methods. In InitializeAsync, it always comes back with:

libplctag.LibPlcTagException: 'ErrorTimeout'

Same happens with ReadAsync. If I instead use the synchronous methods Initialize() and Read(), and leave everything else as is, it works fine. The async methods work fine with the ab_eip protocol, it's just the protocol modbus_tcp where I get the exceptions.

Am I missing something here?

timyhac commented 1 year ago

There is no special handling for modbus in the wrapper. Can you post some debug logs?

nc-koko commented 1 year ago

Which logs do you need, and where can I find them?

timyhac commented 1 year ago

Please see this example that shows how to collection libplctag debug logs. https://github.com/libplctag/libplctag.NET/blob/master/src/Examples/CSharp%20DotNetCore/LoggingExample.cs

nc-koko commented 1 year ago

Here is the log:

Info            2022-11-21 11:45:32.909 thread(1) tag(0) INFO plc_tag_create_ex:833 Starting
Info            2022-11-21 11:45:32.920 thread(1) tag(0) INFO initialize_modules:177 Starting.
Info            2022-11-21 11:45:32.920 thread(1) tag(0) INFO initialize_modules:186 Creating library mutex.
Detail          2022-11-21 11:45:32.920 thread(1) tag(0) DETAIL mutex_create:726 Starting.
Detail          2022-11-21 11:45:32.920 thread(1) tag(0) DETAIL mutex_create:753 Done.
Info            2022-11-21 11:45:32.920 thread(1) tag(0) INFO initialize_modules:207 Initialized library modules.
Info            2022-11-21 11:45:32.920 thread(1) tag(0) INFO lib_init:135 Setting up global library data.
Info            2022-11-21 11:45:32.920 thread(1) tag(0) INFO lib_init:137 Creating tag hashtable.
Info            2022-11-21 11:45:32.920 thread(1) tag(0) INFO hashtable_create:75 Starting
Info            2022-11-21 11:45:32.920 thread(1) tag(0) INFO hashtable_create:99 Done
Info            2022-11-21 11:45:32.920 thread(1) tag(0) INFO lib_init:143 Creating tag hashtable mutex.
Detail          2022-11-21 11:45:32.920 thread(1) tag(0) DETAIL mutex_create:726 Starting.
Detail          2022-11-21 11:45:32.920 thread(1) tag(0) DETAIL mutex_create:753 Done.
Info            2022-11-21 11:45:32.921 thread(1) tag(0) INFO lib_init:149 Creating tag condition variable.
Detail          2022-11-21 11:45:32.921 thread(1) tag(0) DETAIL cond_create:1087 Starting.
Detail          2022-11-21 11:45:32.921 thread(1) tag(0) DETAIL cond_create:1114 Done.
Info            2022-11-21 11:45:32.921 thread(1) tag(0) INFO lib_init:155 Creating tag tickler thread.
Detail          2022-11-21 11:45:32.921 thread(1) tag(0) DETAIL thread_create:884 Starting.
Detail          2022-11-21 11:45:32.921 thread(1) tag(0) DETAIL thread_create:917 Done.
Info            2022-11-21 11:45:32.921 thread(1) tag(0) INFO lib_init:161 Done.
Info            2022-11-21 11:45:32.921 thread(1) tag(0) INFO initialize_modules:210 Initializing AB module.
Info            2022-11-21 11:45:32.921 thread(2) tag(0) INFO tag_tickler_func:508 Starting.
Info            2022-11-21 11:45:32.921 thread(1) tag(0) INFO ab_init:123 Initializing AB protocol library.
Detail          2022-11-21 11:45:32.921 thread(1) tag(0) DETAIL mutex_create:726 Starting.
Detail          2022-11-21 11:45:32.921 thread(1) tag(0) DETAIL mutex_create:753 Done.
Info            2022-11-21 11:45:32.921 thread(1) tag(0) INFO ab_init:132 Finished initializing AB protocol library.
Info            2022-11-21 11:45:32.921 thread(1) tag(0) INFO initialize_modules:215 Initializing Modbus module.
Info            2022-11-21 11:45:32.921 thread(1) tag(0) INFO mb_init:2410 Starting.
Detail          2022-11-21 11:45:32.921 thread(1) tag(0) DETAIL mb_init:2412 Setting up mutex.
Detail          2022-11-21 11:45:32.921 thread(1) tag(0) DETAIL mutex_create:726 Starting.
Detail          2022-11-21 11:45:32.921 thread(1) tag(0) DETAIL mutex_create:753 Done.
Info            2022-11-21 11:45:32.923 thread(1) tag(0) INFO mb_init:2421 Done.
Info            2022-11-21 11:45:32.924 thread(1) tag(0) INFO initialize_modules:226 Done initializing library modules.
Info            2022-11-21 11:45:32.924 thread(1) tag(0) INFO initialize_modules:231 Done.
Info            2022-11-21 11:45:32.924 thread(1) tag(0) INFO find_tag_create_func:99 Matched protocol=modbus_tcp
Info            2022-11-21 11:45:32.924 thread(1) tag(0) INFO mb_tag_create:276 Starting.
Info            2022-11-21 11:45:32.925 thread(1) tag(0) INFO create_tag_object:332 Starting.
Info            2022-11-21 11:45:32.925 thread(1) tag(0) INFO parse_register_name:1983 Starting.
Detail          2022-11-21 11:45:32.925 thread(1) tag(0) DETAIL parse_register_name:2007 Found holding register type.
Info            2022-11-21 11:45:32.925 thread(1) tag(0) INFO parse_register_name:2019 Done.
Detail          2022-11-21 11:45:32.925 thread(1) tag(0) DETAIL create_tag_object:367 Tag data size is 2 bytes.
Info            2022-11-21 11:45:32.926 thread(1) tag(0) INFO rc_alloc_impl:111 Starting, called from create_tag_object:370
Info            2022-11-21 11:45:32.926 thread(1) tag(0) INFO rc_alloc_impl:130 Done
Detail          2022-11-21 11:45:32.926 thread(1) tag(0) DETAIL rc_alloc_impl:135 Returning memory pointer 08557B18
Info            2022-11-21 11:45:32.926 thread(1) tag(0) INFO create_tag_object:401 Done.
Info            2022-11-21 11:45:32.926 thread(1) tag(0) INFO plc_tag_generic_init_tag:462 Starting.
Detail          2022-11-21 11:45:32.927 thread(1) tag(0) DETAIL mutex_create:726 Starting.
Detail          2022-11-21 11:45:32.927 thread(1) tag(0) DETAIL mutex_create:753 Done.
Detail          2022-11-21 11:45:32.927 thread(1) tag(0) DETAIL mutex_create:726 Starting.
Detail          2022-11-21 11:45:32.927 thread(1) tag(0) DETAIL mutex_create:753 Done.
Detail          2022-11-21 11:45:32.927 thread(1) tag(0) DETAIL cond_create:1087 Starting.
Detail          2022-11-21 11:45:32.929 thread(1) tag(0) DETAIL cond_create:1114 Done.
Info            2022-11-21 11:45:32.929 thread(1) tag(0) INFO plc_tag_generic_init_tag:493 Done.
Info            2022-11-21 11:45:32.930 thread(1) tag(0) INFO find_or_create_plc:475 Starting.
Detail          2022-11-21 11:45:32.930 thread(1) tag(0) DETAIL find_or_create_plc:509 Creating new PLC connection.
Info            2022-11-21 11:45:32.930 thread(1) tag(0) INFO rc_alloc_impl:111 Starting, called from find_or_create_plc:513
Info            2022-11-21 11:45:32.931 thread(1) tag(0) INFO rc_alloc_impl:130 Done
Detail          2022-11-21 11:45:32.931 thread(1) tag(0) DETAIL rc_alloc_impl:135 Returning memory pointer 08642B88
Detail          2022-11-21 11:45:32.931 thread(1) tag(0) DETAIL find_or_create_plc:515 Setting connection_group_id to 0.Detail          2022-11-21 11:45:32.932 thread(1) tag(0) DETAIL mutex_create:726 Starting.
Detail          2022-11-21 11:45:32.932 thread(1) tag(0) DETAIL mutex_create:753 Done.
Info            2022-11-21 11:45:32.932 thread(1) tag(0) INFO find_or_create_plc:559 Creating new PLC.
Detail          2022-11-21 11:45:32.933 thread(1) tag(0) DETAIL thread_create:884 Starting.
Detail          2022-11-21 11:45:32.933 thread(1) tag(0) DETAIL thread_create:917 Done.
Detail          2022-11-21 11:45:32.934 thread(1) tag(0) DETAIL find_or_create_plc:574 Created thread 08600980.
Info            2022-11-21 11:45:32.934 thread(1) tag(0) INFO find_or_create_plc:586 Done.
Detail          2022-11-21 11:45:32.935 thread(1) tag(0) DETAIL mb_read_start:2219 Starting.
Info            2022-11-21 11:45:32.935 thread(3) tag(0) INFO modbus_plc_handler:680 Starting.
Detail          2022-11-21 11:45:32.935 thread(1) tag(0) DETAIL wake_plc_thread:926 Starting.
Detail          2022-11-21 11:45:32.936 thread(3) tag(0) DETAIL tickle_all_tags:1028 Starting.
Detail          2022-11-21 11:45:32.936 thread(1) tag(0) DETAIL wake_plc_thread:932 PLC socket pointer is NULL.
Detail          2022-11-21 11:45:32.936 thread(3) tag(0) DETAIL find_request_slot:1321 PLC not ready.
Detail          2022-11-21 11:45:32.936 thread(1) tag(0) DETAIL wake_plc_thread:938 Done.
Detail          2022-11-21 11:45:32.936 thread(3) tag(0) DETAIL plc_tag_generic_tickler:276 Tickling tag 0.
Detail          2022-11-21 11:45:32.937 thread(1) tag(0) DETAIL mb_read_start:2244 Done.
Detail          2022-11-21 11:45:32.937 thread(3) tag(0) DETAIL plc_tag_generic_tickler:381 Done.
Info            2022-11-21 11:45:32.937 thread(1) tag(0) INFO mb_tag_create:308 Done.
Detail          2022-11-21 11:45:32.937 thread(3) tag(0) DETAIL tickle_all_tags:1077 Done: PLCTAG_STATUS_OK
Info            2022-11-21 11:45:32.938 thread(1) tag(0) INFO set_tag_byte_order:3859 Starting.
Detail          2022-11-21 11:45:32.938 thread(3) tag(0) DETAIL modbus_plc_handler:703 in PLC_CONNECT_START state.
Info            2022-11-21 11:45:32.938 thread(1) tag(0) INFO set_tag_byte_order:4160 Done.
Detail          2022-11-21 11:45:32.938 thread(3) tag(0) DETAIL connect_plc:950 Starting.
Detail          2022-11-21 11:45:32.938 thread(1) tag(0) DETAIL add_tag_lookup:4263 Starting.
Detail          2022-11-21 11:45:32.939 thread(3) tag(0) DETAIL connect_plc:978 Using server "10.106.2.20" and port 502.Detail          2022-11-21 11:45:32.939 thread(1) tag(0) DETAIL add_tag_lookup:4283 Found unused ID 11
Detail          2022-11-21 11:45:32.939 thread(3) tag(0) DETAIL socket_create:1311 Starting.
Detail          2022-11-21 11:45:32.939 thread(1) tag(0) DETAIL add_tag_lookup:4303 Done.
Info            2022-11-21 11:45:32.940 thread(1) tag(11) INFO plc_tag_create_ex:959 Returning mapped tag ID 11
Detail          2022-11-21 11:45:32.940 thread(1) tag(11) DETAIL mb_wake_plc:2330 Starting.
Detail          2022-11-21 11:45:32.940 thread(1) tag(11) DETAIL wake_plc_thread:926 Starting.
Detail          2022-11-21 11:45:32.940 thread(1) tag(11) DETAIL wake_plc_thread:932 PLC socket pointer is NULL.
Detail          2022-11-21 11:45:32.941 thread(1) tag(11) DETAIL wake_plc_thread:938 Done.
Detail          2022-11-21 11:45:32.941 thread(1) tag(11) DETAIL mb_wake_plc:2340 Done.
Detail          2022-11-21 11:45:32.941 thread(1) tag(11) DETAIL mb_tag_status:2255 Starting.
Detail          2022-11-21 11:45:32.941 thread(1) tag(11) DETAIL mb_tag_status:2268 Operation in progress, returning PLCTAG_STATUS_PENDING.
Detail          2022-11-21 11:45:32.942 thread(1) tag(11) DETAIL plc_tag_create_ex:985 Tag status after creation is PLCTAG_STATUS_PENDING.
Detail          2022-11-21 11:45:32.941 thread(3) tag(0) DETAIL socket_create:1334 Done.
Info            2022-11-21 11:45:32.942 thread(1) tag(11) INFO plc_tag_create_ex:1060 Done.
Detail          2022-11-21 11:45:32.942 thread(3) tag(0) DETAIL connect_plc:991 Connecting to 10.106.2.20 on port 502...Detail          2022-11-21 11:45:32.942 thread(3) tag(0) DETAIL socket_connect_tcp_start:1355 Starting.
Info            2022-11-21 11:45:32.943 thread(1) tag(11) INFO plc_tag_register_callback:1125 Starting.
Detail          2022-11-21 11:45:32.945 thread(3) tag(0) DETAIL socket_connect_tcp_start:1404 Found numeric IP address: 10.106.2.20
Info            2022-11-21 11:45:32.946 thread(1) tag(11) INFO plc_tag_register_callback_ex:1180 Starting.
Detail          2022-11-21 11:45:32.947 thread(3) tag(0) DETAIL socket_connect_tcp_start:1444 Setting up wake pipe.
Info            2022-11-21 11:45:32.947 thread(1) tag(11) INFO plc_tag_register_callback_ex:1203 Done.
Info            2022-11-21 11:45:32.947 thread(3) tag(0) INFO sock_create_event_wakeup_channel:2161 Starting.
Info            2022-11-21 11:45:32.947 thread(1) tag(11) INFO plc_tag_register_callback:1129 Done.
Info            2022-11-21 11:45:32.948 thread(3) tag(0) INFO sock_create_event_wakeup_channel:2308 Done.
Detail          2022-11-21 11:45:32.948 thread(1) tag(11) DETAIL mb_tag_status:2255 Starting.
Detail          2022-11-21 11:45:32.948 thread(3) tag(0) DETAIL socket_connect_tcp_start:1475 Socket connection attempt 0 started successfully.
Detail          2022-11-21 11:45:32.948 thread(1) tag(11) DETAIL mb_tag_status:2268 Operation in progress, returning PLCTAG_STATUS_PENDING.
Detail          2022-11-21 11:45:32.949 thread(3) tag(0) DETAIL socket_connect_tcp_start:1501 Done.
Detail          2022-11-21 11:45:32.949 thread(3) tag(0) DETAIL connect_plc:1015 Done with status PLCTAG_STATUS_PENDING.Detail          2022-11-21 11:45:32.949 thread(3) tag(0) DETAIL modbus_plc_handler:708 Socket connection process started.  Going to PLC_CONNECT_WAIT state.
Detail          2022-11-21 11:45:32.950 thread(3) tag(0) DETAIL tickle_all_tags:1028 Starting.
Detail          2022-11-21 11:45:32.950 thread(3) tag(11) DETAIL find_request_slot:1321 PLC not ready.
Detail          2022-11-21 11:45:32.950 thread(3) tag(11) DETAIL plc_tag_generic_tickler:276 Tickling tag 11.
Detail          2022-11-21 11:45:32.950 thread(3) tag(11) DETAIL plc_tag_generic_tickler:381 Done.
Detail          2022-11-21 11:45:32.951 thread(3) tag(0) DETAIL tickle_all_tags:1077 Done: PLCTAG_STATUS_OK
Detail          2022-11-21 11:45:32.951 thread(3) tag(0) DETAIL socket_connect_tcp_check:1518 Starting.
Detail          2022-11-21 11:45:32.974 thread(3) tag(0) DETAIL socket_connect_tcp_check:1548 Socket connection not done yet.
Detail          2022-11-21 11:45:32.975 thread(3) tag(0) DETAIL socket_connect_tcp_check:1598 Done.
Detail          2022-11-21 11:45:32.975 thread(3) tag(0) DETAIL modbus_plc_handler:744 Still waiting for socket to connect.
Detail          2022-11-21 11:45:32.977 thread(3) tag(0) DETAIL tickle_all_tags:1028 Starting.
Detail          2022-11-21 11:45:32.977 thread(3) tag(11) DETAIL find_request_slot:1321 PLC not ready.
Detail          2022-11-21 11:45:32.978 thread(3) tag(11) DETAIL plc_tag_generic_tickler:276 Tickling tag 11.
Detail          2022-11-21 11:45:32.978 thread(3) tag(11) DETAIL plc_tag_generic_tickler:381 Done.
Detail          2022-11-21 11:45:32.979 thread(3) tag(0) DETAIL tickle_all_tags:1077 Done: PLCTAG_STATUS_OK
Detail          2022-11-21 11:45:32.979 thread(3) tag(0) DETAIL socket_connect_tcp_check:1518 Starting.
Detail          2022-11-21 11:45:32.992 thread(3) tag(0) DETAIL socket_connect_tcp_check:1538 Socket is connected.
Detail          2022-11-21 11:45:32.992 thread(3) tag(0) DETAIL socket_connect_tcp_check:1598 Done.
Detail          2022-11-21 11:45:32.992 thread(3) tag(0) DETAIL modbus_plc_handler:734 Socket connected, going to state PLC_READY.
Detail          2022-11-21 11:45:32.992 thread(3) tag(0) DETAIL tickle_all_tags:1028 Starting.
Detail          2022-11-21 11:45:32.994 thread(3) tag(11) DETAIL find_request_slot:1333 Found request slot 0 for tag 11.Detail          2022-11-21 11:45:32.994 thread(3) tag(11) DETAIL create_read_request:1521 Starting.
Detail          2022-11-21 11:45:32.994 thread(3) tag(11) DETAIL create_read_request:1523 seq_id=1
Detail          2022-11-21 11:45:32.994 thread(3) tag(11) DETAIL create_read_request:1524 registers_per_request = 125
Detail          2022-11-21 11:45:32.995 thread(3) tag(11) DETAIL create_read_request:1525 base_register = 5301
Detail          2022-11-21 11:45:32.995 thread(3) tag(11) DETAIL create_read_request:1526 register_count = 1
Info            2022-11-21 11:45:32.995 thread(3) tag(11) INFO create_read_request:1533 preparing read request for 1 registers (of 1 total) from base register 5301.
Detail          2022-11-21 11:45:32.995 thread(3) tag(11) DETAIL create_read_request:1604 Created read request:
Detail          2022-11-21 11:45:32.995 thread(3) tag(11) DETAIL create_read_request:1605  00 01 00 00 00 06 00 03 14 b5Detail          2022-11-21 11:45:32.996 thread(3) tag(11) DETAIL create_read_request:1605  00 01
Detail          2022-11-21 11:45:32.996 thread(3) tag(11) DETAIL create_read_request:1607 Done.
Detail          2022-11-21 11:45:32.996 thread(3) tag(11) DETAIL tickle_tag:1102 Read request created.
Detail          2022-11-21 11:45:32.996 thread(3) tag(11) DETAIL plc_tag_generic_tickler:276 Tickling tag 11.
Detail          2022-11-21 11:45:32.997 thread(3) tag(11) DETAIL plc_tag_generic_tickler:381 Done.
Detail          2022-11-21 11:45:32.997 thread(3) tag(0) DETAIL tickle_all_tags:1077 Done: PLCTAG_STATUS_OK
Detail          2022-11-21 11:45:32.997 thread(3) tag(0) DETAIL modbus_plc_handler:762 in PLC_READY state.
Detail          2022-11-21 11:45:32.997 thread(3) tag(0) DETAIL socket_wait_event:1612 Starting.
Detail          2022-11-21 11:45:32.998 thread(3) tag(0) DETAIL socket_wait_event:1701 Socket can write or just connected.
Detail          2022-11-21 11:45:32.998 thread(3) tag(0) DETAIL socket_wait_event:1758 Done.
Detail          2022-11-21 11:45:32.998 thread(3) tag(0) DETAIL modbus_plc_handler:794 There is a request ready to send and we can send, going to state PLC_SEND_REQUEST.
Detail          2022-11-21 11:45:32.998 thread(3) tag(0) DETAIL tickle_all_tags:1028 Starting.
Detail          2022-11-21 11:45:32.998 thread(3) tag(11) DETAIL plc_tag_generic_tickler:276 Tickling tag 11.
Detail          2022-11-21 11:45:32.999 thread(3) tag(11) DETAIL plc_tag_generic_tickler:381 Done.
Detail          2022-11-21 11:45:32.999 thread(3) tag(0) DETAIL tickle_all_tags:1077 Done: PLCTAG_STATUS_OK
Detail          2022-11-21 11:45:32.999 thread(3) tag(11) DETAIL modbus_plc_handler:823 in PLC_SEND_REQUEST state.
Detail          2022-11-21 11:45:32.999 thread(3) tag(11) DETAIL send_request:1456 Starting.
Detail          2022-11-21 11:45:32.999 thread(3) tag(11) DETAIL socket_write:1945 Starting.
Detail          2022-11-21 11:45:33.000 thread(3) tag(11) DETAIL socket_write:2072 Done: result = 12.
Detail          2022-11-21 11:45:33.000 thread(3) tag(11) DETAIL send_request:1490 Full packet written.
Detail          2022-11-21 11:45:33.000 thread(3) tag(11) DETAIL send_request:1491  00 01 00 00 00 06 00 03 14 b5
Detail          2022-11-21 11:45:33.000 thread(3) tag(11) DETAIL send_request:1491  00 01
Detail          2022-11-21 11:45:33.001 thread(3) tag(11) DETAIL send_request:1505 Done.
Detail          2022-11-21 11:45:33.001 thread(3) tag(11) DETAIL modbus_plc_handler:827 Request sent, going to back to state PLC_READY.
Detail          2022-11-21 11:45:33.001 thread(3) tag(0) DETAIL tickle_all_tags:1028 Starting.
Detail          2022-11-21 11:45:33.001 thread(3) tag(11) DETAIL plc_tag_generic_tickler:276 Tickling tag 11.
Detail          2022-11-21 11:45:33.002 thread(3) tag(11) DETAIL plc_tag_generic_tickler:381 Done.
Detail          2022-11-21 11:45:33.003 thread(3) tag(0) DETAIL tickle_all_tags:1077 Done: PLCTAG_STATUS_OK
Detail          2022-11-21 11:45:33.003 thread(3) tag(0) DETAIL modbus_plc_handler:762 in PLC_READY state.
Detail          2022-11-21 11:45:33.004 thread(3) tag(0) DETAIL socket_wait_event:1612 Starting.
Detail          2022-11-21 11:45:33.037 thread(2) tag(0) DETAIL tag_tickler_func:631 Tag tickler thread timed out waiting for something to do.
Detail          2022-11-21 11:45:33.037 thread(2) tag(11) DETAIL tag_tickler_func:602 Tag has its own tickler.
Detail          2022-11-21 11:45:33.071 thread(3) tag(0) DETAIL socket_wait_event:1691 Socket can read.
Detail          2022-11-21 11:45:33.071 thread(3) tag(0) DETAIL socket_wait_event:1758 Done.
Detail          2022-11-21 11:45:33.071 thread(3) tag(0) DETAIL modbus_plc_handler:806 We can receive a response going to state PLC_RECEIVE_RESPONSE.
Detail          2022-11-21 11:45:33.071 thread(3) tag(0) DETAIL tickle_all_tags:1028 Starting.
Detail          2022-11-21 11:45:33.072 thread(3) tag(11) DETAIL plc_tag_generic_tickler:276 Tickling tag 11.
Detail          2022-11-21 11:45:33.072 thread(3) tag(11) DETAIL plc_tag_generic_tickler:381 Done.
Detail          2022-11-21 11:45:33.072 thread(3) tag(0) DETAIL tickle_all_tags:1077 Done: PLCTAG_STATUS_OK
Detail          2022-11-21 11:45:33.072 thread(3) tag(0) DETAIL modbus_plc_handler:860 in PLC_RECEIVE_RESPONSE state.
Detail          2022-11-21 11:45:33.073 thread(3) tag(0) DETAIL receive_response:1374 Starting.
Detail          2022-11-21 11:45:33.073 thread(3) tag(0) DETAIL receive_response:1399 Still reading packet header, data_needed=6, read_data_len=0
Detail          2022-11-21 11:45:33.073 thread(3) tag(0) DETAIL socket_read:1807 Starting.
Detail          2022-11-21 11:45:33.073 thread(3) tag(0) DETAIL socket_read:1934 Done: result = 6.
Detail          2022-11-21 11:45:33.074 thread(3) tag(0) DETAIL receive_response:1422 After reading the socket, total read=6 and data needed=6.
Detail          2022-11-21 11:45:33.074 thread(3) tag(0) DETAIL receive_response:1388 Packet header read, data_needed=5, packet_size=5, read_data_len=6
Detail          2022-11-21 11:45:33.075 thread(3) tag(0) DETAIL socket_read:1807 Starting.
Detail          2022-11-21 11:45:33.075 thread(3) tag(0) DETAIL socket_read:1934 Done: result = 5.
Detail          2022-11-21 11:45:33.075 thread(3) tag(0) DETAIL receive_response:1422 After reading the socket, total read=11 and data needed=5.
Detail          2022-11-21 11:45:33.076 thread(3) tag(0) DETAIL receive_response:1388 Packet header read, data_needed=0, packet_size=5, read_data_len=11
Detail          2022-11-21 11:45:33.076 thread(3) tag(0) DETAIL receive_response:1403 Got all data needed.
Detail          2022-11-21 11:45:33.076 thread(3) tag(0) DETAIL receive_response:1428 Received full packet.
Detail          2022-11-21 11:45:33.076 thread(3) tag(0) DETAIL receive_response:1429  00 01 00 00 00 05 00 03 02 1d
Detail          2022-11-21 11:45:33.076 thread(3) tag(0) DETAIL receive_response:1429  72
Detail          2022-11-21 11:45:33.077 thread(3) tag(0) DETAIL receive_response:1444 Done.
Detail          2022-11-21 11:45:33.077 thread(3) tag(0) DETAIL modbus_plc_handler:865 Response ready, going back to PLC_READY state.
Detail          2022-11-21 11:45:33.077 thread(3) tag(0) DETAIL tickle_all_tags:1028 Starting.
Detail          2022-11-21 11:45:33.077 thread(3) tag(11) DETAIL check_read_response:1636 Starting.
Detail          2022-11-21 11:45:33.078 thread(3) tag(11) DETAIL check_read_response:1656 Got read response 1 of length 11 with payload of size 2.
Detail          2022-11-21 11:45:33.078 thread(3) tag(11) DETAIL check_read_response:1657 registers_per_request = 125
Detail          2022-11-21 11:45:33.078 thread(3) tag(11) DETAIL check_read_response:1658 register_offset = 0
Detail          2022-11-21 11:45:33.078 thread(3) tag(11) DETAIL check_read_response:1659 byte_offset = 0
Detail          2022-11-21 11:45:33.078 thread(3) tag(11) DETAIL check_read_response:1660 copy_size = 2
Detail          2022-11-21 11:45:33.079 thread(3) tag(11) DETAIL check_read_response:1671 Read is complete.
Detail          2022-11-21 11:45:33.079 thread(3) tag(11) DETAIL check_read_response:1684 Read is complete.  Cleaning up tag state.
Detail          2022-11-21 11:45:33.079 thread(3) tag(11) DETAIL check_read_response:1702 Done: PLCTAG_STATUS_OK
Detail          2022-11-21 11:45:33.079 thread(3) tag(11) DETAIL tickle_tag:1142 Found our response.
Detail          2022-11-21 11:45:33.079 thread(3) tag(11) DETAIL clear_request_slot:1348 Starting for tag 11.
Detail          2022-11-21 11:45:33.080 thread(3) tag(11) DETAIL clear_request_slot:1353 Found tag 11 in slot 0.
Detail          2022-11-21 11:45:33.080 thread(3) tag(11) DETAIL clear_request_slot:1364 Done for tag 11.
Detail          2022-11-21 11:45:33.080 thread(3) tag(11) DETAIL plc_tag_tickler_wake_impl:215 Starting. Called from tickle_tag:1151.
Detail          2022-11-21 11:45:33.080 thread(3) tag(11) DETAIL plc_tag_tickler_wake_impl:228 Done. Called from tickle_tag:1151.
Detail          2022-11-21 11:45:33.080 thread(2) tag(11) DETAIL tag_tickler_func:602 Tag has its own tickler.
Detail          2022-11-21 11:45:33.081 thread(3) tag(11) DETAIL plc_tag_generic_wake_tag_impl:239 Starting. Called from tickle_tag:1152.
Detail          2022-11-21 11:45:33.081 thread(3) tag(11) DETAIL plc_tag_generic_wake_tag_impl:257 Done. Called from tickle_tag:1152.
Detail          2022-11-21 11:45:33.081 thread(3) tag(11) DETAIL plc_tag_generic_tickler:276 Tickling tag 11.
Detail          2022-11-21 11:45:33.081 thread(3) tag(11) DETAIL plc_tag_generic_tickler:381 Done.
Detail          2022-11-21 11:45:33.082 thread(3) tag(0) DETAIL tickle_all_tags:1077 Done: PLCTAG_STATUS_OK
Detail          2022-11-21 11:45:33.082 thread(3) tag(0) DETAIL modbus_plc_handler:762 in PLC_READY state.
Detail          2022-11-21 11:45:33.083 thread(3) tag(0) DETAIL socket_wait_event:1612 Starting.
Detail          2022-11-21 11:45:33.193 thread(3) tag(0) DETAIL socket_wait_event:1758 Done.
Detail          2022-11-21 11:45:33.194 thread(3) tag(0) DETAIL modbus_plc_handler:812 Timed out waiting for something to happen.
Detail          2022-11-21 11:45:33.193 thread(2) tag(0) DETAIL tag_tickler_func:631 Tag tickler thread timed out waiting for something to do.
Detail          2022-11-21 11:45:33.197 thread(3) tag(0) DETAIL tickle_all_tags:1028 Starting.
Detail          2022-11-21 11:45:33.199 thread(2) tag(11) DETAIL tag_tickler_func:602 Tag has its own tickler.
Detail          2022-11-21 11:45:33.201 thread(3) tag(11) DETAIL plc_tag_generic_tickler:276 Tickling tag 11.
Detail          2022-11-21 11:45:33.204 thread(3) tag(11) DETAIL plc_tag_generic_tickler:381 Done.
Detail          2022-11-21 11:45:33.205 thread(3) tag(0) DETAIL tickle_all_tags:1077 Done: PLCTAG_STATUS_OK
Detail          2022-11-21 11:45:33.206 thread(3) tag(0) DETAIL modbus_plc_handler:762 in PLC_READY state.
Detail          2022-11-21 11:45:33.210 thread(3) tag(0) DETAIL socket_wait_event:1612 Starting.
Detail          2022-11-21 11:45:33.302 thread(2) tag(0) DETAIL tag_tickler_func:631 Tag tickler thread timed out waiting for something to do.
Detail          2022-11-21 11:45:33.303 thread(2) tag(11) DETAIL tag_tickler_func:602 Tag has its own tickler.
Detail          2022-11-21 11:45:33.317 thread(3) tag(0) DETAIL socket_wait_event:1758 Done.
Detail          2022-11-21 11:45:33.317 thread(3) tag(0) DETAIL modbus_plc_handler:812 Timed out waiting for something to happen.
Detail          2022-11-21 11:45:33.318 thread(3) tag(0) DETAIL tickle_all_tags:1028 Starting.
Detail          2022-11-21 11:45:33.318 thread(3) tag(11) DETAIL plc_tag_generic_tickler:276 Tickling tag 11.
Detail          2022-11-21 11:45:33.318 thread(3) tag(11) DETAIL plc_tag_generic_tickler:381 Done.
Detail          2022-11-21 11:45:33.318 thread(3) tag(0) DETAIL tickle_all_tags:1077 Done: PLCTAG_STATUS_OK
Detail          2022-11-21 11:45:33.319 thread(3) tag(0) DETAIL modbus_plc_handler:762 in PLC_READY state.
Detail          2022-11-21 11:45:33.319 thread(3) tag(0) DETAIL socket_wait_event:1612 Starting.
Detail          2022-11-21 11:45:33.410 thread(2) tag(0) DETAIL tag_tickler_func:631 Tag tickler thread timed out waiting for something to do.
Detail          2022-11-21 11:45:33.411 thread(2) tag(11) DETAIL tag_tickler_func:602 Tag has its own tickler.
Detail          2022-11-21 11:45:33.425 thread(3) tag(0) DETAIL socket_wait_event:1758 Done.
Detail          2022-11-21 11:45:33.427 thread(3) tag(0) DETAIL modbus_plc_handler:812 Timed out waiting for something to happen.
Detail          2022-11-21 11:45:33.428 thread(3) tag(0) DETAIL tickle_all_tags:1028 Starting.
Detail          2022-11-21 11:45:33.429 thread(3) tag(11) DETAIL plc_tag_generic_tickler:276 Tickling tag 11.
Detail          2022-11-21 11:45:33.430 thread(3) tag(11) DETAIL plc_tag_generic_tickler:381 Done.
Detail          2022-11-21 11:45:33.430 thread(3) tag(0) DETAIL tickle_all_tags:1077 Done: PLCTAG_STATUS_OK
Detail          2022-11-21 11:45:33.431 thread(3) tag(0) DETAIL modbus_plc_handler:762 in PLC_READY state.
Detail          2022-11-21 11:45:33.431 thread(3) tag(0) DETAIL socket_wait_event:1612 Starting.
Detail          2022-11-21 11:45:33.519 thread(2) tag(0) DETAIL tag_tickler_func:631 Tag tickler thread timed out waiting for something to do.
Detail          2022-11-21 11:45:33.520 thread(2) tag(11) DETAIL tag_tickler_func:602 Tag has its own tickler.
Detail          2022-11-21 11:45:33.534 thread(3) tag(0) DETAIL socket_wait_event:1758 Done.
Detail          2022-11-21 11:45:33.536 thread(3) tag(0) DETAIL modbus_plc_handler:812 Timed out waiting for something to happen.
Detail          2022-11-21 11:45:33.537 thread(3) tag(0) DETAIL tickle_all_tags:1028 Starting.
Detail          2022-11-21 11:45:33.537 thread(3) tag(11) DETAIL plc_tag_generic_tickler:276 Tickling tag 11.
Detail          2022-11-21 11:45:33.538 thread(3) tag(11) DETAIL plc_tag_generic_tickler:381 Done.
Detail          2022-11-21 11:45:33.538 thread(3) tag(0) DETAIL tickle_all_tags:1077 Done: PLCTAG_STATUS_OK
Detail          2022-11-21 11:45:33.538 thread(3) tag(0) DETAIL modbus_plc_handler:762 in PLC_READY state.
Detail          2022-11-21 11:45:33.538 thread(3) tag(0) DETAIL socket_wait_event:1612 Starting.
Detail          2022-11-21 11:45:33.628 thread(2) tag(0) DETAIL tag_tickler_func:631 Tag tickler thread timed out waiting for something to do.
Detail          2022-11-21 11:45:33.630 thread(2) tag(11) DETAIL tag_tickler_func:602 Tag has its own tickler.
Detail          2022-11-21 11:45:33.643 thread(3) tag(0) DETAIL socket_wait_event:1758 Done.
Detail          2022-11-21 11:45:33.649 thread(3) tag(0) DETAIL modbus_plc_handler:812 Timed out waiting for something to happen.
Detail          2022-11-21 11:45:33.651 thread(3) tag(0) DETAIL tickle_all_tags:1028 Starting.
Detail          2022-11-21 11:45:33.652 thread(3) tag(11) DETAIL plc_tag_generic_tickler:276 Tickling tag 11.
Detail          2022-11-21 11:45:33.653 thread(3) tag(11) DETAIL plc_tag_generic_tickler:381 Done.
Detail          2022-11-21 11:45:33.653 thread(3) tag(0) DETAIL tickle_all_tags:1077 Done: PLCTAG_STATUS_OK
Detail          2022-11-21 11:45:33.654 thread(3) tag(0) DETAIL modbus_plc_handler:762 in PLC_READY state.
Detail          2022-11-21 11:45:33.655 thread(3) tag(0) DETAIL socket_wait_event:1612 Starting.
Detail          2022-11-21 11:45:33.738 thread(2) tag(0) DETAIL tag_tickler_func:631 Tag tickler thread timed out waiting for something to do.
Detail          2022-11-21 11:45:33.739 thread(2) tag(11) DETAIL tag_tickler_func:602 Tag has its own tickler.
Detail          2022-11-21 11:45:33.768 thread(3) tag(0) DETAIL socket_wait_event:1758 Done.
Detail          2022-11-21 11:45:33.768 thread(3) tag(0) DETAIL modbus_plc_handler:812 Timed out waiting for something to happen.
Detail          2022-11-21 11:45:33.769 thread(3) tag(0) DETAIL tickle_all_tags:1028 Starting.
Detail          2022-11-21 11:45:33.770 thread(3) tag(11) DETAIL plc_tag_generic_tickler:276 Tickling tag 11.
Detail          2022-11-21 11:45:33.770 thread(3) tag(11) DETAIL plc_tag_generic_tickler:381 Done.
Detail          2022-11-21 11:45:33.771 thread(3) tag(0) DETAIL tickle_all_tags:1077 Done: PLCTAG_STATUS_OK
Detail          2022-11-21 11:45:33.771 thread(3) tag(0) DETAIL modbus_plc_handler:762 in PLC_READY state.
Detail          2022-11-21 11:45:33.771 thread(3) tag(0) DETAIL socket_wait_event:1612 Starting.
Detail          2022-11-21 11:45:33.846 thread(2) tag(0) DETAIL tag_tickler_func:631 Tag tickler thread timed out waiting for something to do.
Detail          2022-11-21 11:45:33.847 thread(2) tag(11) DETAIL tag_tickler_func:602 Tag has its own tickler.
Detail          2022-11-21 11:45:33.877 thread(3) tag(0) DETAIL socket_wait_event:1758 Done.
Detail          2022-11-21 11:45:33.877 thread(3) tag(0) DETAIL modbus_plc_handler:812 Timed out waiting for something to happen.
Detail          2022-11-21 11:45:33.879 thread(3) tag(0) DETAIL tickle_all_tags:1028 Starting.
Detail          2022-11-21 11:45:33.879 thread(3) tag(11) DETAIL plc_tag_generic_tickler:276 Tickling tag 11.
Detail          2022-11-21 11:45:33.879 thread(3) tag(11) DETAIL plc_tag_generic_tickler:381 Done.
Detail          2022-11-21 11:45:33.880 thread(3) tag(0) DETAIL tickle_all_tags:1077 Done: PLCTAG_STATUS_OK
Detail          2022-11-21 11:45:33.880 thread(3) tag(0) DETAIL modbus_plc_handler:762 in PLC_READY state.
Detail          2022-11-21 11:45:33.880 thread(3) tag(0) DETAIL socket_wait_event:1612 Starting.
Info            2022-11-21 11:45:33.912 thread(4) tag(11) INFO plc_tag_abort:1419 Starting.
Detail          2022-11-21 11:45:33.912 thread(4) tag(11) DETAIL mb_abort:2183 Starting.
Detail          2022-11-21 11:45:33.912 thread(4) tag(11) DETAIL clear_request_slot:1348 Starting for tag 11.
Detail          2022-11-21 11:45:33.912 thread(4) tag(11) DETAIL clear_request_slot:1364 Done for tag 11.
Detail          2022-11-21 11:45:33.913 thread(4) tag(11) DETAIL wake_plc_thread:926 Starting.
Detail          2022-11-21 11:45:33.913 thread(4) tag(11) DETAIL socket_wake:1770 Starting.
Detail          2022-11-21 11:45:33.913 thread(4) tag(11) DETAIL socket_wake:1796 Done.
Detail          2022-11-21 11:45:33.913 thread(4) tag(11) DETAIL wake_plc_thread:938 Done.
Detail          2022-11-21 11:45:33.913 thread(3) tag(0) DETAIL socket_wait_event:1678 Socket woken up.
Detail          2022-11-21 11:45:33.914 thread(4) tag(11) DETAIL mb_abort:2208 Done.
Detail          2022-11-21 11:45:33.914 thread(4) tag(11) DETAIL tag_raise_event:186 PLCTAG_EVENT_ABORTED raised with status PLCTAG_ERR_ABORT.
Detail          2022-11-21 11:45:33.914 thread(4) tag(11) DETAIL tag_raise_event:190 Raising synthesized created event on abort event.
Detail          2022-11-21 11:45:33.914 thread(3) tag(0) DETAIL socket_wait_event:1758 Done.
Detail          2022-11-21 11:45:33.914 thread(4) tag(11) DETAIL plc_tag_tickler_wake_impl:215 Starting. Called from plc_tag_abort:1448.
Detail          2022-11-21 11:45:33.915 thread(3) tag(0) DETAIL modbus_plc_handler:816 Someone woke us up.
Detail          2022-11-21 11:45:33.915 thread(4) tag(11) DETAIL plc_tag_tickler_wake_impl:228 Done. Called from plc_tag_abort:1448.
Detail          2022-11-21 11:45:33.915 thread(2) tag(11) DETAIL tag_tickler_func:602 Tag has its own tickler.
Detail          2022-11-21 11:45:33.915 thread(3) tag(0) DETAIL tickle_all_tags:1028 Starting.
Detail          2022-11-21 11:45:33.915 thread(4) tag(11) DETAIL plc_tag_generic_handle_event_callbacks:397 Tag creation complete with status PLCTAG_ERR_ABORT.
Detail          2022-11-21 11:45:33.916 thread(4) tag(11) DETAIL plc_tag_generic_handle_event_callbacks:421 Tag operation aborted with status PLCTAG_ERR_ABORT.
Info            2022-11-21 11:45:33.917 thread(4) tag(0) INFO plc_tag_abort:1454 Done.
Detail          2022-11-21 11:45:33.917 thread(3) tag(11) DETAIL plc_tag_generic_tickler:276 Tickling tag 11.
Detail          2022-11-21 11:45:33.917 thread(3) tag(11) DETAIL plc_tag_generic_tickler:381 Done.
Detail          2022-11-21 11:45:33.917 thread(3) tag(0) DETAIL tickle_all_tags:1077 Done: PLCTAG_STATUS_OK
Info            2022-11-21 11:45:33.917 thread(4) tag(11) INFO plc_tag_unregister_callback:1226 Starting.
Detail          2022-11-21 11:45:33.917 thread(3) tag(0) DETAIL modbus_plc_handler:762 in PLC_READY state.
Info            2022-11-21 11:45:33.918 thread(4) tag(11) INFO plc_tag_unregister_callback:1245 Done.
Detail          2022-11-21 11:45:33.918 thread(3) tag(0) DETAIL socket_wait_event:1612 Starting.
Detail          2022-11-21 11:45:34.031 thread(3) tag(0) DETAIL socket_wait_event:1758 Done.
Detail          2022-11-21 11:45:34.031 thread(2) tag(0) DETAIL tag_tickler_func:631 Tag tickler thread timed out waiting for something to do.
Detail          2022-11-21 11:45:35.093 thread(3) tag(0) DETAIL modbus_plc_handler:812 Timed out waiting for something to happen.
Detail          2022-11-21 11:45:35.093 thread(2) tag(11) DETAIL tag_tickler_func:602 Tag has its own tickler.
Detail          2022-11-21 11:45:35.094 thread(3) tag(0) DETAIL tickle_all_tags:1028 Starting.
Detail          2022-11-21 11:45:35.094 thread(3) tag(11) DETAIL plc_tag_generic_tickler:276 Tickling tag 11.
Detail          2022-11-21 11:45:35.095 thread(3) tag(11) DETAIL plc_tag_generic_tickler:381 Done.
Detail          2022-11-21 11:45:35.096 thread(3) tag(0) DETAIL tickle_all_tags:1077 Done: PLCTAG_STATUS_OK
Detail          2022-11-21 11:45:35.196 thread(2) tag(0) DETAIL tag_tickler_func:631 Tag tickler thread timed out waiting for something to do.
Unhandled exception. Detail             2022-11-21 11:45:35.994 thread(3) tag(0) DETAIL modbus_plc_handler:762 in PLC_READY state.
Detail          2022-11-21 11:45:35.994 thread(2) tag(11) DETAIL tag_tickler_func:602 Tag has its own tickler.
Detail          2022-11-21 11:45:35.995 thread(3) tag(0) DETAIL socket_wait_event:1612 Starting.
libplctag.LibPlcTagException: ErrorTimeout
   at libplctag.NativeTagWrapper.InitializeAsync(CancellationToken token) in C:\Users\NK\test5\libplctag.NET\src\libplctag\NativeTagWrapper.cs:line 346
   at libplctag.Tag`2.InitializeAsync(CancellationToken token) in C:\Users\NK\test5\libplctag.NET\src\libplctag\TagOfT.cs:line 155
   at CSharpDotNetCore.ExampleAsync.Run() in C:\Users\NK\test5\libplctag.NET\src\Examples\CSharp DotNetCore\ExampleAsync.cs:line 37
   at CSharpDotNetCore.Program.Main(String[] args) in C:\Users\NK\test5\libplctag.NET\src\Examples\CSharp DotNetCore\Program.cs:line 31
   at CSharpDotNetCore.Program.<Main>(String[] args)
kyle-github commented 1 year ago

I can see the TCP connection get set up. Then I see the initial read. That works. Then there's nothing at all from outside the library. I don't see any attempts to start another read.

I don't see any logging about tag created events or read events completing. I wonder if there is a problem in the core library here. Let me do some investigation to make sure all the events are getting sent correctly.

Also, it looks like the new(ish) tag create function is not being used, so there isn't a callback during the early part of the tag and PLC connection set up. It is possible that the event is being missed due to that.

timyhac commented 1 year ago

Also, it looks like the new(ish) tag create function is not being used, so there isn't a callback during the early part of the tag and PLC connection set up. It is possible that the event is being missed due to that.

I'm not sure how I missed this, this is probably it - libplctag.NET does not use plc_tag_create_ex yet - good eyes!

timyhac commented 1 year ago

@nc-koko - there is some work on this front in this branch.

@jkoplo - ok if we release this as 1.1.1-alpha?

jkoplo commented 1 year ago

Do you want me to do a quick review in that branch before we cut a release?

But yeah, if there's a new method we missed we should probably update the pre-release packages asap.

timyhac commented 1 year ago

Hi @nc-koko - an alpha package v1.1.1-alpha.0 has been released with a fix - could you please test it out?

nc-koko commented 1 year ago

I'm still seeing the same exception. Here's the debug log

Info            2022-11-25 11:51:19.764 thread(1) tag(0) INFO plc_tag_create_ex:833 Starting
Info            2022-11-25 11:51:19.776 thread(1) tag(0) INFO initialize_modules:177 Starting.
Info            2022-11-25 11:51:19.776 thread(1) tag(0) INFO initialize_modules:186 Creating library mutex.
Detail          2022-11-25 11:51:19.776 thread(1) tag(0) DETAIL mutex_create:726 Starting.
Detail          2022-11-25 11:51:19.776 thread(1) tag(0) DETAIL mutex_create:753 Done.
Info            2022-11-25 11:51:19.776 thread(1) tag(0) INFO initialize_modules:207 Initialized library modules.
Info            2022-11-25 11:51:19.777 thread(1) tag(0) INFO lib_init:135 Setting up global library data.
Info            2022-11-25 11:51:19.777 thread(1) tag(0) INFO lib_init:137 Creating tag hashtable.
Info            2022-11-25 11:51:19.777 thread(1) tag(0) INFO hashtable_create:75 Starting
Info            2022-11-25 11:51:19.777 thread(1) tag(0) INFO hashtable_create:99 Done
Info            2022-11-25 11:51:19.777 thread(1) tag(0) INFO lib_init:143 Creating tag hashtable mutex.
Detail          2022-11-25 11:51:19.777 thread(1) tag(0) DETAIL mutex_create:726 Starting.
Detail          2022-11-25 11:51:19.777 thread(1) tag(0) DETAIL mutex_create:753 Done.
Info            2022-11-25 11:51:19.777 thread(1) tag(0) INFO lib_init:149 Creating tag condition variable.
Detail          2022-11-25 11:51:19.777 thread(1) tag(0) DETAIL cond_create:1087 Starting.
Detail          2022-11-25 11:51:19.778 thread(1) tag(0) DETAIL cond_create:1114 Done.
Info            2022-11-25 11:51:19.778 thread(1) tag(0) INFO lib_init:155 Creating tag tickler thread.
Detail          2022-11-25 11:51:19.778 thread(1) tag(0) DETAIL thread_create:884 Starting.
Detail          2022-11-25 11:51:19.778 thread(1) tag(0) DETAIL thread_create:917 Done.
Info            2022-11-25 11:51:19.778 thread(1) tag(0) INFO lib_init:161 Done.
Info            2022-11-25 11:51:19.778 thread(1) tag(0) INFO initialize_modules:210 Initializing AB module.
Info            2022-11-25 11:51:19.778 thread(2) tag(0) INFO tag_tickler_func:508 Starting.
Info            2022-11-25 11:51:19.779 thread(1) tag(0) INFO ab_init:123 Initializing AB protocol library.
Detail          2022-11-25 11:51:19.779 thread(1) tag(0) DETAIL mutex_create:726 Starting.
Detail          2022-11-25 11:51:19.779 thread(1) tag(0) DETAIL mutex_create:753 Done.
Info            2022-11-25 11:51:19.779 thread(1) tag(0) INFO ab_init:132 Finished initializing AB protocol library.
Info            2022-11-25 11:51:19.779 thread(1) tag(0) INFO initialize_modules:215 Initializing Modbus module.
Info            2022-11-25 11:51:19.780 thread(1) tag(0) INFO mb_init:2410 Starting.
Detail          2022-11-25 11:51:19.780 thread(1) tag(0) DETAIL mb_init:2412 Setting up mutex.
Detail          2022-11-25 11:51:19.780 thread(1) tag(0) DETAIL mutex_create:726 Starting.
Detail          2022-11-25 11:51:19.780 thread(1) tag(0) DETAIL mutex_create:753 Done.
Info            2022-11-25 11:51:19.780 thread(1) tag(0) INFO mb_init:2421 Done.
Info            2022-11-25 11:51:19.780 thread(1) tag(0) INFO initialize_modules:226 Done initializing library modules.
Info            2022-11-25 11:51:19.781 thread(1) tag(0) INFO initialize_modules:231 Done.
Detail          2022-11-25 11:51:19.783 thread(1) tag(0) DETAIL attr_create_from_str:131 Starting.
Detail          2022-11-25 11:51:19.783 thread(1) tag(0) DETAIL attr_create_from_str:160 Key-value pair "protocol=modbus_tcp".
Detail          2022-11-25 11:51:19.784 thread(1) tag(0) DETAIL attr_create_from_str:175 Key-value pair before trimming "protocol":"modbus_tcp".
Detail          2022-11-25 11:51:19.785 thread(1) tag(0) DETAIL attr_create_from_str:187 Key-value pair after trimming "protocol":"modbus_tcp".
Detail          2022-11-25 11:51:19.785 thread(1) tag(0) DETAIL attr_create_from_str:160 Key-value pair "gateway=10.106.2.20".
Detail          2022-11-25 11:51:19.786 thread(1) tag(0) DETAIL attr_create_from_str:175 Key-value pair before trimming "gateway":"10.106.2.20".
Detail          2022-11-25 11:51:19.786 thread(1) tag(0) DETAIL attr_create_from_str:187 Key-value pair after trimming "gateway":"10.106.2.20".
Detail          2022-11-25 11:51:19.787 thread(1) tag(0) DETAIL attr_create_from_str:160 Key-value pair "path=0".
Detail          2022-11-25 11:51:19.789 thread(1) tag(0) DETAIL attr_create_from_str:175 Key-value pair before trimming "path":"0".
Detail          2022-11-25 11:51:19.789 thread(1) tag(0) DETAIL attr_create_from_str:187 Key-value pair after trimming "path":"0".
Detail          2022-11-25 11:51:19.790 thread(1) tag(0) DETAIL attr_create_from_str:160 Key-value pair "plc=controllogix".
Detail          2022-11-25 11:51:19.790 thread(1) tag(0) DETAIL attr_create_from_str:175 Key-value pair before trimming "plc":"controllogix".
Detail          2022-11-25 11:51:19.791 thread(1) tag(0) DETAIL attr_create_from_str:187 Key-value pair after trimming "plc":"controllogix".
Detail          2022-11-25 11:51:19.793 thread(1) tag(0) DETAIL attr_create_from_str:160 Key-value pair "elem_size=4".
Detail          2022-11-25 11:51:19.793 thread(1) tag(0) DETAIL attr_create_from_str:175 Key-value pair before trimming "elem_size":"4".
Detail          2022-11-25 11:51:19.794 thread(1) tag(0) DETAIL attr_create_from_str:187 Key-value pair after trimming "elem_size":"4".
Detail          2022-11-25 11:51:19.794 thread(1) tag(0) DETAIL attr_create_from_str:160 Key-value pair "name=hr5301".
Detail          2022-11-25 11:51:19.794 thread(1) tag(0) DETAIL attr_create_from_str:175 Key-value pair before trimming "name":"hr5301".
Detail          2022-11-25 11:51:19.794 thread(1) tag(0) DETAIL attr_create_from_str:187 Key-value pair after trimming "name":"hr5301".
Detail          2022-11-25 11:51:19.795 thread(1) tag(0) DETAIL attr_create_from_str:218 Done.
Info            2022-11-25 11:51:19.795 thread(1) tag(0) INFO find_tag_create_func:99 Matched protocol=modbus_tcp
Info            2022-11-25 11:51:19.795 thread(1) tag(0) INFO mb_tag_create:276 Starting.
Info            2022-11-25 11:51:19.796 thread(1) tag(0) INFO create_tag_object:332 Starting.
Info            2022-11-25 11:51:19.796 thread(1) tag(0) INFO parse_register_name:1983 Starting.
Detail          2022-11-25 11:51:19.796 thread(1) tag(0) DETAIL parse_register_name:2007 Found holding register type.
Info            2022-11-25 11:51:19.796 thread(1) tag(0) INFO parse_register_name:2019 Done.
Detail          2022-11-25 11:51:19.796 thread(1) tag(0) DETAIL create_tag_object:367 Tag data size is 2 bytes.
Info            2022-11-25 11:51:19.797 thread(1) tag(0) INFO rc_alloc_impl:111 Starting, called from create_tag_object:370
Info            2022-11-25 11:51:19.797 thread(1) tag(0) INFO rc_alloc_impl:130 Done
Detail          2022-11-25 11:51:19.797 thread(1) tag(0) DETAIL rc_alloc_impl:135 Returning memory pointer 088A3FF0
Info            2022-11-25 11:51:19.797 thread(1) tag(0) INFO create_tag_object:401 Done.
Info            2022-11-25 11:51:19.798 thread(1) tag(0) INFO plc_tag_generic_init_tag:462 Starting.
Detail          2022-11-25 11:51:19.798 thread(1) tag(0) DETAIL mutex_create:726 Starting.
Detail          2022-11-25 11:51:19.798 thread(1) tag(0) DETAIL mutex_create:753 Done.
Detail          2022-11-25 11:51:19.798 thread(1) tag(0) DETAIL mutex_create:726 Starting.
Detail          2022-11-25 11:51:19.798 thread(1) tag(0) DETAIL mutex_create:753 Done.
Detail          2022-11-25 11:51:19.799 thread(1) tag(0) DETAIL cond_create:1087 Starting.
Detail          2022-11-25 11:51:19.799 thread(1) tag(0) DETAIL cond_create:1114 Done.
Info            2022-11-25 11:51:19.799 thread(1) tag(0) INFO plc_tag_generic_init_tag:493 Done.
Info            2022-11-25 11:51:19.799 thread(1) tag(0) INFO find_or_create_plc:475 Starting.
Detail          2022-11-25 11:51:19.799 thread(1) tag(0) DETAIL find_or_create_plc:509 Creating new PLC connection.
Info            2022-11-25 11:51:19.800 thread(1) tag(0) INFO rc_alloc_impl:111 Starting, called from find_or_create_plc:513
Info            2022-11-25 11:51:19.800 thread(1) tag(0) INFO rc_alloc_impl:130 Done
Detail          2022-11-25 11:51:19.800 thread(1) tag(0) DETAIL rc_alloc_impl:135 Returning memory pointer 0897F990
Detail          2022-11-25 11:51:19.800 thread(1) tag(0) DETAIL find_or_create_plc:515 Setting connection_group_id to 0.
Detail          2022-11-25 11:51:19.801 thread(1) tag(0) DETAIL mutex_create:726 Starting.
Detail          2022-11-25 11:51:19.801 thread(1) tag(0) DETAIL mutex_create:753 Done.
Info            2022-11-25 11:51:19.801 thread(1) tag(0) INFO find_or_create_plc:559 Creating new PLC.
Detail          2022-11-25 11:51:19.801 thread(1) tag(0) DETAIL thread_create:884 Starting.
Detail          2022-11-25 11:51:19.802 thread(1) tag(0) DETAIL thread_create:917 Done.
Detail          2022-11-25 11:51:19.802 thread(1) tag(0) DETAIL find_or_create_plc:574 Created thread 08934740.
Info            2022-11-25 11:51:19.802 thread(1) tag(0) INFO find_or_create_plc:586 Done.
Info            2022-11-25 11:51:19.802 thread(3) tag(0) INFO modbus_plc_handler:680 Starting.
Detail          2022-11-25 11:51:19.802 thread(1) tag(0) DETAIL mb_read_start:2219 Starting.
Detail          2022-11-25 11:51:19.803 thread(1) tag(0) DETAIL wake_plc_thread:926 Starting.
Detail          2022-11-25 11:51:19.802 thread(3) tag(0) DETAIL tickle_all_tags:1028 Starting.
Detail          2022-11-25 11:51:19.803 thread(1) tag(0) DETAIL wake_plc_thread:932 PLC socket pointer is NULL.
Detail          2022-11-25 11:51:19.803 thread(1) tag(0) DETAIL wake_plc_thread:938 Done.
Detail          2022-11-25 11:51:19.803 thread(3) tag(0) DETAIL find_request_slot:1321 PLC not ready.
Detail          2022-11-25 11:51:19.804 thread(1) tag(0) DETAIL mb_read_start:2244 Done.
Info            2022-11-25 11:51:19.804 thread(1) tag(0) INFO mb_tag_create:308 Done.
Detail          2022-11-25 11:51:19.804 thread(3) tag(0) DETAIL plc_tag_generic_tickler:276 Tickling tag 0.
Info            2022-11-25 11:51:19.804 thread(1) tag(0) INFO set_tag_byte_order:3859 Starting.
Detail          2022-11-25 11:51:19.804 thread(3) tag(0) DETAIL plc_tag_generic_tickler:381 Done.
Info            2022-11-25 11:51:19.805 thread(1) tag(0) INFO set_tag_byte_order:4160 Done.
Detail          2022-11-25 11:51:19.805 thread(3) tag(0) DETAIL tickle_all_tags:1077 Done: PLCTAG_STATUS_OK
Detail          2022-11-25 11:51:19.805 thread(1) tag(0) DETAIL add_tag_lookup:4263 Starting.
Detail          2022-11-25 11:51:19.805 thread(3) tag(0) DETAIL modbus_plc_handler:703 in PLC_CONNECT_START state.
Detail          2022-11-25 11:51:19.806 thread(1) tag(0) DETAIL add_tag_lookup:4283 Found unused ID 11
Detail          2022-11-25 11:51:19.809 thread(3) tag(0) DETAIL connect_plc:950 Starting.
Detail          2022-11-25 11:51:19.813 thread(1) tag(0) DETAIL add_tag_lookup:4303 Done.
Detail          2022-11-25 11:51:19.814 thread(3) tag(0) DETAIL connect_plc:978 Using server "10.106.2.20" and port 502.
Info            2022-11-25 11:51:19.814 thread(1) tag(11) INFO plc_tag_create_ex:959 Returning mapped tag ID 11
Detail          2022-11-25 11:51:19.815 thread(3) tag(0) DETAIL socket_create:1311 Starting.
Detail          2022-11-25 11:51:19.815 thread(1) tag(11) DETAIL mb_wake_plc:2330 Starting.
Detail          2022-11-25 11:51:19.816 thread(1) tag(11) DETAIL wake_plc_thread:926 Starting.
Detail          2022-11-25 11:51:19.817 thread(1) tag(11) DETAIL wake_plc_thread:932 PLC socket pointer is NULL.
Detail          2022-11-25 11:51:19.817 thread(1) tag(11) DETAIL wake_plc_thread:938 Done.
Detail          2022-11-25 11:51:19.818 thread(1) tag(11) DETAIL mb_wake_plc:2340 Done.
Detail          2022-11-25 11:51:19.818 thread(3) tag(0) DETAIL socket_create:1334 Done.
Detail          2022-11-25 11:51:19.818 thread(1) tag(11) DETAIL mb_tag_status:2255 Starting.
Detail          2022-11-25 11:51:19.818 thread(3) tag(0) DETAIL connect_plc:991 Connecting to 10.106.2.20 on port 502...
Detail          2022-11-25 11:51:19.819 thread(1) tag(11) DETAIL mb_tag_status:2268 Operation in progress, returning PLCTAG_STATUS_PENDING.
Detail          2022-11-25 11:51:19.819 thread(3) tag(0) DETAIL socket_connect_tcp_start:1355 Starting.
Detail          2022-11-25 11:51:19.819 thread(1) tag(11) DETAIL plc_tag_create_ex:985 Tag status after creation is PLCTAG_STATUS_PENDING.
Info            2022-11-25 11:51:19.820 thread(1) tag(0) INFO plc_tag_create_ex:1060 Done.
Detail          2022-11-25 11:51:19.821 thread(1) tag(11) DETAIL mb_tag_status:2255 Starting.
Detail          2022-11-25 11:51:19.822 thread(1) tag(11) DETAIL mb_tag_status:2268 Operation in progress, returning PLCTAG_STATUS_PENDING.
Detail          2022-11-25 11:51:19.837 thread(3) tag(0) DETAIL socket_connect_tcp_start:1404 Found numeric IP address: 10.106.2.20
Detail          2022-11-25 11:51:19.839 thread(3) tag(0) DETAIL socket_connect_tcp_start:1444 Setting up wake pipe.
Info            2022-11-25 11:51:19.841 thread(3) tag(0) INFO sock_create_event_wakeup_channel:2161 Starting.
Info            2022-11-25 11:51:19.842 thread(3) tag(0) INFO sock_create_event_wakeup_channel:2308 Done.
Detail          2022-11-25 11:51:19.843 thread(3) tag(0) DETAIL socket_connect_tcp_start:1475 Socket connection attempt 0 started successfully.
Detail          2022-11-25 11:51:19.843 thread(3) tag(0) DETAIL socket_connect_tcp_start:1501 Done.
Detail          2022-11-25 11:51:19.843 thread(3) tag(0) DETAIL connect_plc:1015 Done with status PLCTAG_STATUS_PENDING.
Detail          2022-11-25 11:51:19.844 thread(3) tag(0) DETAIL modbus_plc_handler:708 Socket connection process started.  Going to PLC_CONNECT_WAIT state.
Detail          2022-11-25 11:51:19.844 thread(3) tag(0) DETAIL tickle_all_tags:1028 Starting.
Detail          2022-11-25 11:51:19.844 thread(3) tag(11) DETAIL find_request_slot:1321 PLC not ready.
Detail          2022-11-25 11:51:19.844 thread(3) tag(11) DETAIL plc_tag_generic_tickler:276 Tickling tag 11.
Detail          2022-11-25 11:51:19.845 thread(3) tag(11) DETAIL plc_tag_generic_tickler:381 Done.
Detail          2022-11-25 11:51:19.845 thread(3) tag(0) DETAIL tickle_all_tags:1077 Done: PLCTAG_STATUS_OK
Detail          2022-11-25 11:51:19.845 thread(3) tag(0) DETAIL socket_connect_tcp_check:1518 Starting.
Detail          2022-11-25 11:51:19.867 thread(3) tag(0) DETAIL socket_connect_tcp_check:1548 Socket connection not done yet.
Detail          2022-11-25 11:51:19.868 thread(3) tag(0) DETAIL socket_connect_tcp_check:1598 Done.
Detail          2022-11-25 11:51:19.868 thread(3) tag(0) DETAIL modbus_plc_handler:744 Still waiting for socket to connect.
Detail          2022-11-25 11:51:19.868 thread(3) tag(0) DETAIL tickle_all_tags:1028 Starting.
Detail          2022-11-25 11:51:19.869 thread(3) tag(11) DETAIL find_request_slot:1321 PLC not ready.
Detail          2022-11-25 11:51:19.869 thread(3) tag(11) DETAIL plc_tag_generic_tickler:276 Tickling tag 11.
Detail          2022-11-25 11:51:19.869 thread(3) tag(11) DETAIL plc_tag_generic_tickler:381 Done.
Detail          2022-11-25 11:51:19.870 thread(3) tag(0) DETAIL tickle_all_tags:1077 Done: PLCTAG_STATUS_OK
Detail          2022-11-25 11:51:19.870 thread(3) tag(0) DETAIL socket_connect_tcp_check:1518 Starting.
Detail          2022-11-25 11:51:19.883 thread(2) tag(0) DETAIL tag_tickler_func:631 Tag tickler thread timed out waiting for something to do.
Detail          2022-11-25 11:51:19.884 thread(2) tag(11) DETAIL tag_tickler_func:602 Tag has its own tickler.
Detail          2022-11-25 11:51:19.887 thread(3) tag(0) DETAIL socket_connect_tcp_check:1538 Socket is connected.
Detail          2022-11-25 11:51:19.887 thread(3) tag(0) DETAIL socket_connect_tcp_check:1598 Done.
Detail          2022-11-25 11:51:19.887 thread(3) tag(0) DETAIL modbus_plc_handler:734 Socket connected, going to state PLC_READY.
Detail          2022-11-25 11:51:19.888 thread(3) tag(0) DETAIL tickle_all_tags:1028 Starting.
Detail          2022-11-25 11:51:19.888 thread(3) tag(11) DETAIL find_request_slot:1333 Found request slot 0 for tag 11.
Detail          2022-11-25 11:51:19.888 thread(3) tag(11) DETAIL create_read_request:1521 Starting.
Detail          2022-11-25 11:51:19.888 thread(3) tag(11) DETAIL create_read_request:1523 seq_id=1
Detail          2022-11-25 11:51:19.888 thread(3) tag(11) DETAIL create_read_request:1524 registers_per_request = 125
Detail          2022-11-25 11:51:19.889 thread(3) tag(11) DETAIL create_read_request:1525 base_register = 5301
Detail          2022-11-25 11:51:19.889 thread(3) tag(11) DETAIL create_read_request:1526 register_count = 1
Info            2022-11-25 11:51:19.889 thread(3) tag(11) INFO create_read_request:1533 preparing read request for 1 registers (of 1 total) from base register 5301.
Detail          2022-11-25 11:51:19.889 thread(3) tag(11) DETAIL create_read_request:1604 Created read request:
Detail          2022-11-25 11:51:19.890 thread(3) tag(11) DETAIL create_read_request:1605  00 01 00 00 00 06 00 03 14 b5
Detail          2022-11-25 11:51:19.890 thread(3) tag(11) DETAIL create_read_request:1605  00 01
Detail          2022-11-25 11:51:19.890 thread(3) tag(11) DETAIL create_read_request:1607 Done.
Detail          2022-11-25 11:51:19.890 thread(3) tag(11) DETAIL tickle_tag:1102 Read request created.
Detail          2022-11-25 11:51:19.890 thread(3) tag(11) DETAIL plc_tag_generic_tickler:276 Tickling tag 11.
Detail          2022-11-25 11:51:19.891 thread(3) tag(11) DETAIL plc_tag_generic_tickler:381 Done.
Detail          2022-11-25 11:51:19.891 thread(3) tag(0) DETAIL tickle_all_tags:1077 Done: PLCTAG_STATUS_OK
Detail          2022-11-25 11:51:19.891 thread(3) tag(0) DETAIL modbus_plc_handler:762 in PLC_READY state.
Detail          2022-11-25 11:51:19.891 thread(3) tag(0) DETAIL socket_wait_event:1612 Starting.
Detail          2022-11-25 11:51:19.892 thread(3) tag(0) DETAIL socket_wait_event:1701 Socket can write or just connected.
Detail          2022-11-25 11:51:19.892 thread(3) tag(0) DETAIL socket_wait_event:1758 Done.
Detail          2022-11-25 11:51:19.892 thread(3) tag(0) DETAIL modbus_plc_handler:794 There is a request ready to send and we can send, going to state PLC_SEND_REQUEST.
Detail          2022-11-25 11:51:19.892 thread(3) tag(0) DETAIL tickle_all_tags:1028 Starting.
Detail          2022-11-25 11:51:19.892 thread(3) tag(11) DETAIL plc_tag_generic_tickler:276 Tickling tag 11.
Detail          2022-11-25 11:51:19.893 thread(3) tag(11) DETAIL plc_tag_generic_tickler:381 Done.
Detail          2022-11-25 11:51:19.893 thread(3) tag(0) DETAIL tickle_all_tags:1077 Done: PLCTAG_STATUS_OK
Detail          2022-11-25 11:51:19.893 thread(3) tag(11) DETAIL modbus_plc_handler:823 in PLC_SEND_REQUEST state.
Detail          2022-11-25 11:51:19.893 thread(3) tag(11) DETAIL send_request:1456 Starting.
Detail          2022-11-25 11:51:19.894 thread(3) tag(11) DETAIL socket_write:1945 Starting.
Detail          2022-11-25 11:51:19.894 thread(3) tag(11) DETAIL socket_write:2072 Done: result = 12.
Detail          2022-11-25 11:51:19.894 thread(3) tag(11) DETAIL send_request:1490 Full packet written.
Detail          2022-11-25 11:51:19.894 thread(3) tag(11) DETAIL send_request:1491  00 01 00 00 00 06 00 03 14 b5
Detail          2022-11-25 11:51:19.894 thread(3) tag(11) DETAIL send_request:1491  00 01
Detail          2022-11-25 11:51:19.895 thread(3) tag(11) DETAIL send_request:1505 Done.
Detail          2022-11-25 11:51:19.895 thread(3) tag(11) DETAIL modbus_plc_handler:827 Request sent, going to back to state PLC_READY.
Detail          2022-11-25 11:51:19.895 thread(3) tag(0) DETAIL tickle_all_tags:1028 Starting.
Detail          2022-11-25 11:51:19.895 thread(3) tag(11) DETAIL plc_tag_generic_tickler:276 Tickling tag 11.
Detail          2022-11-25 11:51:19.896 thread(3) tag(11) DETAIL plc_tag_generic_tickler:381 Done.
Detail          2022-11-25 11:51:19.896 thread(3) tag(0) DETAIL tickle_all_tags:1077 Done: PLCTAG_STATUS_OK
Detail          2022-11-25 11:51:19.896 thread(3) tag(0) DETAIL modbus_plc_handler:762 in PLC_READY state.
Detail          2022-11-25 11:51:19.896 thread(3) tag(0) DETAIL socket_wait_event:1612 Starting.
Detail          2022-11-25 11:51:19.959 thread(3) tag(0) DETAIL socket_wait_event:1691 Socket can read.
Detail          2022-11-25 11:51:19.959 thread(3) tag(0) DETAIL socket_wait_event:1758 Done.
Detail          2022-11-25 11:51:19.960 thread(3) tag(0) DETAIL modbus_plc_handler:806 We can receive a response going to state PLC_RECEIVE_RESPONSE.
Detail          2022-11-25 11:51:19.960 thread(3) tag(0) DETAIL tickle_all_tags:1028 Starting.
Detail          2022-11-25 11:51:19.960 thread(3) tag(11) DETAIL plc_tag_generic_tickler:276 Tickling tag 11.
Detail          2022-11-25 11:51:19.960 thread(3) tag(11) DETAIL plc_tag_generic_tickler:381 Done.
Detail          2022-11-25 11:51:19.960 thread(3) tag(0) DETAIL tickle_all_tags:1077 Done: PLCTAG_STATUS_OK
Detail          2022-11-25 11:51:19.961 thread(3) tag(0) DETAIL modbus_plc_handler:860 in PLC_RECEIVE_RESPONSE state.
Detail          2022-11-25 11:51:19.961 thread(3) tag(0) DETAIL receive_response:1374 Starting.
Detail          2022-11-25 11:51:19.961 thread(3) tag(0) DETAIL receive_response:1399 Still reading packet header, data_needed=6, read_data_len=0
Detail          2022-11-25 11:51:19.962 thread(3) tag(0) DETAIL socket_read:1807 Starting.
Detail          2022-11-25 11:51:19.962 thread(3) tag(0) DETAIL socket_read:1934 Done: result = 6.
Detail          2022-11-25 11:51:19.962 thread(3) tag(0) DETAIL receive_response:1422 After reading the socket, total read=6 and data needed=6.
Detail          2022-11-25 11:51:19.962 thread(3) tag(0) DETAIL receive_response:1388 Packet header read, data_needed=5, packet_size=5, read_data_len=6
Detail          2022-11-25 11:51:19.962 thread(3) tag(0) DETAIL socket_read:1807 Starting.
Detail          2022-11-25 11:51:19.963 thread(3) tag(0) DETAIL socket_read:1934 Done: result = 5.
Detail          2022-11-25 11:51:19.963 thread(3) tag(0) DETAIL receive_response:1422 After reading the socket, total read=11 and data needed=5.
Detail          2022-11-25 11:51:19.963 thread(3) tag(0) DETAIL receive_response:1388 Packet header read, data_needed=0, packet_size=5, read_data_len=11
Detail          2022-11-25 11:51:19.963 thread(3) tag(0) DETAIL receive_response:1403 Got all data needed.
Detail          2022-11-25 11:51:19.964 thread(3) tag(0) DETAIL receive_response:1428 Received full packet.
Detail          2022-11-25 11:51:19.964 thread(3) tag(0) DETAIL receive_response:1429  00 01 00 00 00 05 00 03 02 20
Detail          2022-11-25 11:51:19.965 thread(3) tag(0) DETAIL receive_response:1429  39
Detail          2022-11-25 11:51:19.965 thread(3) tag(0) DETAIL receive_response:1444 Done.
Detail          2022-11-25 11:51:19.965 thread(3) tag(0) DETAIL modbus_plc_handler:865 Response ready, going back to PLC_READY state.
Detail          2022-11-25 11:51:19.966 thread(3) tag(0) DETAIL tickle_all_tags:1028 Starting.
Detail          2022-11-25 11:51:19.966 thread(3) tag(11) DETAIL check_read_response:1636 Starting.
Detail          2022-11-25 11:51:19.966 thread(3) tag(11) DETAIL check_read_response:1656 Got read response 1 of length 11 with payload of size 2.
Detail          2022-11-25 11:51:19.967 thread(3) tag(11) DETAIL check_read_response:1657 registers_per_request = 125
Detail          2022-11-25 11:51:19.967 thread(3) tag(11) DETAIL check_read_response:1658 register_offset = 0
Detail          2022-11-25 11:51:19.968 thread(3) tag(11) DETAIL check_read_response:1659 byte_offset = 0
Detail          2022-11-25 11:51:19.968 thread(3) tag(11) DETAIL check_read_response:1660 copy_size = 2
Detail          2022-11-25 11:51:19.968 thread(3) tag(11) DETAIL check_read_response:1671 Read is complete.
Detail          2022-11-25 11:51:19.969 thread(3) tag(11) DETAIL check_read_response:1684 Read is complete.  Cleaning up tag state.
Detail          2022-11-25 11:51:19.969 thread(3) tag(11) DETAIL check_read_response:1702 Done: PLCTAG_STATUS_OK
Detail          2022-11-25 11:51:19.969 thread(3) tag(11) DETAIL tickle_tag:1142 Found our response.
Detail          2022-11-25 11:51:19.970 thread(3) tag(11) DETAIL clear_request_slot:1348 Starting for tag 11.
Detail          2022-11-25 11:51:19.971 thread(3) tag(11) DETAIL clear_request_slot:1353 Found tag 11 in slot 0.
Detail          2022-11-25 11:51:19.971 thread(3) tag(11) DETAIL clear_request_slot:1364 Done for tag 11.
Detail          2022-11-25 11:51:19.971 thread(3) tag(11) DETAIL plc_tag_tickler_wake_impl:215 Starting. Called from tickle_tag:1151.
Detail          2022-11-25 11:51:19.972 thread(3) tag(11) DETAIL plc_tag_tickler_wake_impl:228 Done. Called from tickle_tag:1151.
Detail          2022-11-25 11:51:19.972 thread(2) tag(11) DETAIL tag_tickler_func:602 Tag has its own tickler.
Detail          2022-11-25 11:51:19.972 thread(3) tag(11) DETAIL plc_tag_generic_wake_tag_impl:239 Starting. Called from tickle_tag:1152.
Detail          2022-11-25 11:51:19.974 thread(3) tag(11) DETAIL plc_tag_generic_wake_tag_impl:257 Done. Called from tickle_tag:1152.
Detail          2022-11-25 11:51:19.975 thread(3) tag(11) DETAIL plc_tag_generic_tickler:276 Tickling tag 11.
Detail          2022-11-25 11:51:19.977 thread(3) tag(11) DETAIL plc_tag_generic_tickler:381 Done.
Detail          2022-11-25 11:51:19.979 thread(3) tag(0) DETAIL tickle_all_tags:1077 Done: PLCTAG_STATUS_OK
Detail          2022-11-25 11:51:19.979 thread(3) tag(0) DETAIL modbus_plc_handler:762 in PLC_READY state.
Detail          2022-11-25 11:51:19.980 thread(3) tag(0) DETAIL socket_wait_event:1612 Starting.
Detail          2022-11-25 11:51:20.087 thread(2) tag(0) DETAIL tag_tickler_func:631 Tag tickler thread timed out waiting for something to do.
Detail          2022-11-25 11:51:20.087 thread(3) tag(0) DETAIL socket_wait_event:1758 Done.
Detail          2022-11-25 11:51:20.087 thread(2) tag(11) DETAIL tag_tickler_func:602 Tag has its own tickler.
Detail          2022-11-25 11:51:20.087 thread(3) tag(0) DETAIL modbus_plc_handler:812 Timed out waiting for something to happen.
Detail          2022-11-25 11:51:20.090 thread(3) tag(0) DETAIL tickle_all_tags:1028 Starting.
Detail          2022-11-25 11:51:20.090 thread(3) tag(11) DETAIL plc_tag_generic_tickler:276 Tickling tag 11.
Detail          2022-11-25 11:51:20.091 thread(3) tag(11) DETAIL plc_tag_generic_tickler:381 Done.
Detail          2022-11-25 11:51:20.091 thread(3) tag(0) DETAIL tickle_all_tags:1077 Done: PLCTAG_STATUS_OK
Detail          2022-11-25 11:51:20.091 thread(3) tag(0) DETAIL modbus_plc_handler:762 in PLC_READY state.
Detail          2022-11-25 11:51:20.091 thread(3) tag(0) DETAIL socket_wait_event:1612 Starting.
Detail          2022-11-25 11:51:20.196 thread(2) tag(0) DETAIL tag_tickler_func:631 Tag tickler thread timed out waiting for something to do.
Detail          2022-11-25 11:51:20.196 thread(3) tag(0) DETAIL socket_wait_event:1758 Done.
Detail          2022-11-25 11:51:20.197 thread(3) tag(0) DETAIL modbus_plc_handler:812 Timed out waiting for something to happen.
Detail          2022-11-25 11:51:20.197 thread(2) tag(11) DETAIL tag_tickler_func:602 Tag has its own tickler.
Detail          2022-11-25 11:51:20.199 thread(3) tag(0) DETAIL tickle_all_tags:1028 Starting.
Detail          2022-11-25 11:51:20.199 thread(3) tag(11) DETAIL plc_tag_generic_tickler:276 Tickling tag 11.
Detail          2022-11-25 11:51:20.199 thread(3) tag(11) DETAIL plc_tag_generic_tickler:381 Done.
Detail          2022-11-25 11:51:20.200 thread(3) tag(0) DETAIL tickle_all_tags:1077 Done: PLCTAG_STATUS_OK
Detail          2022-11-25 11:51:20.200 thread(3) tag(0) DETAIL modbus_plc_handler:762 in PLC_READY state.
Detail          2022-11-25 11:51:20.200 thread(3) tag(0) DETAIL socket_wait_event:1612 Starting.
Detail          2022-11-25 11:51:20.304 thread(3) tag(0) DETAIL socket_wait_event:1758 Done.
Detail          2022-11-25 11:51:20.304 thread(2) tag(0) DETAIL tag_tickler_func:631 Tag tickler thread timed out waiting for something to do.
Detail          2022-11-25 11:51:20.304 thread(3) tag(0) DETAIL modbus_plc_handler:812 Timed out waiting for something to happen.
Detail          2022-11-25 11:51:20.305 thread(2) tag(11) DETAIL tag_tickler_func:602 Tag has its own tickler.
Detail          2022-11-25 11:51:20.307 thread(3) tag(0) DETAIL tickle_all_tags:1028 Starting.
Detail          2022-11-25 11:51:20.308 thread(3) tag(11) DETAIL plc_tag_generic_tickler:276 Tickling tag 11.
Detail          2022-11-25 11:51:20.308 thread(3) tag(11) DETAIL plc_tag_generic_tickler:381 Done.
Detail          2022-11-25 11:51:20.308 thread(3) tag(0) DETAIL tickle_all_tags:1077 Done: PLCTAG_STATUS_OK
Detail          2022-11-25 11:51:20.308 thread(3) tag(0) DETAIL modbus_plc_handler:762 in PLC_READY state.
Detail          2022-11-25 11:51:20.309 thread(3) tag(0) DETAIL socket_wait_event:1612 Starting.
Detail          2022-11-25 11:51:20.412 thread(2) tag(0) DETAIL tag_tickler_func:631 Tag tickler thread timed out waiting for something to do.
Detail          2022-11-25 11:51:20.412 thread(3) tag(0) DETAIL socket_wait_event:1758 Done.
Detail          2022-11-25 11:51:20.413 thread(3) tag(0) DETAIL modbus_plc_handler:812 Timed out waiting for something to happen.
Detail          2022-11-25 11:51:20.413 thread(2) tag(11) DETAIL tag_tickler_func:602 Tag has its own tickler.
Detail          2022-11-25 11:51:20.415 thread(3) tag(0) DETAIL tickle_all_tags:1028 Starting.
Detail          2022-11-25 11:51:20.416 thread(3) tag(11) DETAIL plc_tag_generic_tickler:276 Tickling tag 11.
Detail          2022-11-25 11:51:20.416 thread(3) tag(11) DETAIL plc_tag_generic_tickler:381 Done.
Detail          2022-11-25 11:51:20.416 thread(3) tag(0) DETAIL tickle_all_tags:1077 Done: PLCTAG_STATUS_OK
Detail          2022-11-25 11:51:20.417 thread(3) tag(0) DETAIL modbus_plc_handler:762 in PLC_READY state.
Detail          2022-11-25 11:51:20.417 thread(3) tag(0) DETAIL socket_wait_event:1612 Starting.
Detail          2022-11-25 11:51:20.521 thread(3) tag(0) DETAIL socket_wait_event:1758 Done.
Detail          2022-11-25 11:51:20.521 thread(2) tag(0) DETAIL tag_tickler_func:631 Tag tickler thread timed out waiting for something to do.
Detail          2022-11-25 11:51:20.521 thread(3) tag(0) DETAIL modbus_plc_handler:812 Timed out waiting for something to happen.
Detail          2022-11-25 11:51:20.522 thread(3) tag(0) DETAIL tickle_all_tags:1028 Starting.
Detail          2022-11-25 11:51:20.522 thread(2) tag(11) DETAIL tag_tickler_func:602 Tag has its own tickler.
Detail          2022-11-25 11:51:20.525 thread(3) tag(11) DETAIL plc_tag_generic_tickler:276 Tickling tag 11.
Detail          2022-11-25 11:51:20.526 thread(3) tag(11) DETAIL plc_tag_generic_tickler:381 Done.
Detail          2022-11-25 11:51:20.527 thread(3) tag(0) DETAIL tickle_all_tags:1077 Done: PLCTAG_STATUS_OK
Detail          2022-11-25 11:51:20.527 thread(3) tag(0) DETAIL modbus_plc_handler:762 in PLC_READY state.
Detail          2022-11-25 11:51:20.527 thread(3) tag(0) DETAIL socket_wait_event:1612 Starting.
Detail          2022-11-25 11:51:20.630 thread(3) tag(0) DETAIL socket_wait_event:1758 Done.
Detail          2022-11-25 11:51:20.630 thread(2) tag(0) DETAIL tag_tickler_func:631 Tag tickler thread timed out waiting for something to do.
Detail          2022-11-25 11:51:20.630 thread(3) tag(0) DETAIL modbus_plc_handler:812 Timed out waiting for something to happen.
Detail          2022-11-25 11:51:20.630 thread(2) tag(11) DETAIL tag_tickler_func:602 Tag has its own tickler.
Detail          2022-11-25 11:51:20.632 thread(3) tag(0) DETAIL tickle_all_tags:1028 Starting.
Detail          2022-11-25 11:51:20.633 thread(3) tag(11) DETAIL plc_tag_generic_tickler:276 Tickling tag 11.
Detail          2022-11-25 11:51:20.633 thread(3) tag(11) DETAIL plc_tag_generic_tickler:381 Done.
Detail          2022-11-25 11:51:20.633 thread(3) tag(0) DETAIL tickle_all_tags:1077 Done: PLCTAG_STATUS_OK
Detail          2022-11-25 11:51:20.634 thread(3) tag(0) DETAIL modbus_plc_handler:762 in PLC_READY state.
Detail          2022-11-25 11:51:20.634 thread(3) tag(0) DETAIL socket_wait_event:1612 Starting.
Detail          2022-11-25 11:51:20.738 thread(3) tag(0) DETAIL socket_wait_event:1758 Done.
Detail          2022-11-25 11:51:20.738 thread(2) tag(0) DETAIL tag_tickler_func:631 Tag tickler thread timed out waiting for something to do.
Detail          2022-11-25 11:51:20.738 thread(3) tag(0) DETAIL modbus_plc_handler:812 Timed out waiting for something to happen.
Detail          2022-11-25 11:51:20.739 thread(2) tag(11) DETAIL tag_tickler_func:602 Tag has its own tickler.
Detail          2022-11-25 11:51:20.739 thread(3) tag(0) DETAIL tickle_all_tags:1028 Starting.
Detail          2022-11-25 11:51:20.740 thread(3) tag(11) DETAIL plc_tag_generic_tickler:276 Tickling tag 11.
Detail          2022-11-25 11:51:20.740 thread(3) tag(11) DETAIL plc_tag_generic_tickler:381 Done.
Detail          2022-11-25 11:51:20.740 thread(3) tag(0) DETAIL tickle_all_tags:1077 Done: PLCTAG_STATUS_OK
Detail          2022-11-25 11:51:20.740 thread(3) tag(0) DETAIL modbus_plc_handler:762 in PLC_READY state.
Detail          2022-11-25 11:51:20.741 thread(3) tag(0) DETAIL socket_wait_event:1612 Starting.
Info            2022-11-25 11:51:20.758 thread(4) tag(11) INFO plc_tag_abort:1419 Starting.
Detail          2022-11-25 11:51:20.758 thread(4) tag(11) DETAIL mb_abort:2183 Starting.
Detail          2022-11-25 11:51:20.759 thread(4) tag(11) DETAIL clear_request_slot:1348 Starting for tag 11.
Detail          2022-11-25 11:51:20.759 thread(4) tag(11) DETAIL clear_request_slot:1364 Done for tag 11.
Detail          2022-11-25 11:51:20.759 thread(4) tag(11) DETAIL wake_plc_thread:926 Starting.
Detail          2022-11-25 11:51:20.760 thread(4) tag(11) DETAIL socket_wake:1770 Starting.
Detail          2022-11-25 11:51:20.760 thread(4) tag(11) DETAIL socket_wake:1796 Done.
Detail          2022-11-25 11:51:20.760 thread(4) tag(11) DETAIL wake_plc_thread:938 Done.
Detail          2022-11-25 11:51:20.760 thread(3) tag(0) DETAIL socket_wait_event:1678 Socket woken up.
Detail          2022-11-25 11:51:20.760 thread(4) tag(11) DETAIL mb_abort:2208 Done.
Detail          2022-11-25 11:51:20.761 thread(3) tag(0) DETAIL socket_wait_event:1758 Done.
Detail          2022-11-25 11:51:20.761 thread(4) tag(11) DETAIL tag_raise_event:186 PLCTAG_EVENT_ABORTED raised with status PLCTAG_ERR_ABORT.
Detail          2022-11-25 11:51:20.762 thread(3) tag(0) DETAIL modbus_plc_handler:816 Someone woke us up.
Detail          2022-11-25 11:51:20.762 thread(4) tag(11) DETAIL tag_raise_event:190 Raising synthesized created event on abort event.
Detail          2022-11-25 11:51:20.763 thread(3) tag(0) DETAIL tickle_all_tags:1028 Starting.
Detail          2022-11-25 11:51:20.763 thread(4) tag(11) DETAIL plc_tag_tickler_wake_impl:215 Starting. Called from plc_tag_abort:1448.
Detail          2022-11-25 11:51:20.763 thread(3) tag(11) DETAIL plc_tag_generic_tickler:276 Tickling tag 11.
Detail          2022-11-25 11:51:20.763 thread(4) tag(11) DETAIL plc_tag_tickler_wake_impl:228 Done. Called from plc_tag_abort:1448.
Detail          2022-11-25 11:51:20.763 thread(2) tag(11) DETAIL tag_tickler_func:602 Tag has its own tickler.
Detail          2022-11-25 11:51:20.764 thread(3) tag(11) DETAIL plc_tag_generic_tickler:381 Done.
Detail          2022-11-25 11:51:20.765 thread(4) tag(11) DETAIL plc_tag_generic_handle_event_callbacks:397 Tag creation complete with status PLCTAG_ERR_ABORT.
Detail          2022-11-25 11:51:20.765 thread(4) tag(11) DETAIL plc_tag_generic_handle_event_callbacks:421 Tag operation aborted with status PLCTAG_ERR_ABORT.
Info            2022-11-25 11:51:20.767 thread(4) tag(0) INFO plc_tag_abort:1454 Done.
Detail          2022-11-25 11:51:20.767 thread(3) tag(0) DETAIL tickle_all_tags:1077 Done: PLCTAG_STATUS_OK
Detail          2022-11-25 11:51:20.768 thread(3) tag(0) DETAIL modbus_plc_handler:762 in PLC_READY state.
Detail          2022-11-25 11:51:20.768 thread(3) tag(0) DETAIL socket_wait_event:1612 Starting.
Info            2022-11-25 11:51:20.768 thread(4) tag(11) INFO plc_tag_unregister_callback:1226 Starting.
Info            2022-11-25 11:51:20.769 thread(4) tag(11) INFO plc_tag_unregister_callback:1245 Done.
kyle-github commented 1 year ago

I don't see any calls to the event dispatch code in this. I do see a few calls to plc_tag_status() but that is only during the tail end of tag creation. It looks like the tag is being created without any timeout on plc_tag_create_ex()?

Let me do some experimentation to see if I can replicate this locally with just the C DLL.

timyhac commented 1 year ago

It looks like the tag is being created without any timeout on plc_tag_create_ex()

That is correct, for Async initialisation we pass in a timeout of 0 and manage the timeout in the wrapper separately.

timyhac commented 1 year ago

After doing some more testing I found an issue relating to synchonous Initialize and have published a new alpha, I don't think that will affect this issue however.

kyle-github commented 1 year ago

This looks a bit odd. The only events I see are aborts. And those are triggered from user code. I do not see any read completion events or creation completion events.

I changed one of the examples to use Modbus and I saw all the events I expected, so they are being generated in the C DLL.

If I had to guess what is happening, I would guess that for some reason the creation completed event is either being missed or there isn't a valid callback when it happens. After that, the user code is just waiting. There are occasional calls to plc_tag_abort() that seem to happen after long periods of time.

If the PLCTAG_EVENT_CREATED event is being missed, then the user code will probably not try to read. There is a read completing, but it is the internally triggered initial read that happens just after the tag is created. I do not even see those events.

The fact that I see some but not others is confusing.

timyhac commented 1 year ago

If someone could point me in the right direction of setting up a local debugging environment I can do a bit more.

I've been using this container as a modbus server: https://hub.docker.com/r/oitc/modbus-server And using this code. It is C# but directly uses the native methods.

var tagHandle = libplctag.NativeImport.plctag.plc_tag_create("protocol=modbus_tcp&gateway=127.0.0.1:5020&path=0&plc=controllogix&elem_size=4&name=hr0", 1000);
var readStatus = (Status)libplctag.NativeImport.plctag.plc_tag_read(tagHandle, 1000);
var value = libplctag.NativeImport.plctag.plc_tag_get_int32(tagHandle, 0);
var status = (Status)libplctag.NativeImport.plctag.plc_tag_status(tagHandle); // ErrorOutOfBounds
kyle-github commented 1 year ago

That looks pretty good. You may want to check the IP address. Is that what your container will run on?

The plc attribute is completely unused. The element size is going to be overridden and will be 2 (Modbus registers are 16 bits).

The default is to read only one element which in this case will be one register, so only 2 bytes. The plc_tag_get_int32() call will fail because there isn't enough data in the tag buffer. You'll get back -2 billion IIRC (INT32_MIN in C). Use plc_tag_get_int16() instead.

Try this as a tag attribute string: protocol=modbus_tcp&gateway=127.0.0.1:5020&path=0&elem_size=2&elem_count=1&name=hr1.

Also Modbus has weird start-from-one counting in some cases. Different devices have different defaults. So hr0 might be illegal for that server. I switched it to hr1 above just to be sure. Based on the comments on the Docker site, I am guessing that this one starts with zero.

timyhac commented 1 year ago

The element size is going to be overridden and will be 2 (Modbus registers are 16 bits). Yep this was the solution, using the plc_tag_get_int16() method works.

I've done some testing and to me it looks like we aren't getting the Created, ReadCompleted and WriteCompleted events when timeout is 0 and using modbus_tcp protocol. I did initially check this with ab_eip protocol with the ab_server simulator and it does work. I can supply some logs for that if I get a chance.

The test creates an int16 tag, writes a value to it, and reads it back.

When using a timeout of 1000, we get all 5 events, and it succesfully writes and then reads the value.

11    | Created              | Ok    | 0
11    | WriteStarted         | Ok    | 0
11    | WriteCompleted       | Ok    | 0
11    | ReadStarted          | Ok    | 0
11    | ReadCompleted        | Ok    | 0

timeout1000.log

When using a timeout of 0, we get these two only

11    | WriteStarted         | Ok    | 0
11    | ReadStarted          | Ok    | 0

timeout0.log

The code listing is below:

public static void Run()
{
    LibPlcTag.LogEvent += LibPlcTag_LogEvent;
    LibPlcTag.DebugLevel = DebugLevel.Detail;

    var timeout = 1000;
    var attributeString = "protocol=modbus_tcp&gateway=127.0.0.1:5020&path=0&elem_size=2&name=hr0";
    var tagHandle = plctag.plc_tag_create_ex(attributeString, eventCallback, IntPtr.Zero, timeout); // 11

    WaitUntilNotPending(tagHandle);

    var setStatus = (Status)plctag.plc_tag_set_int16(tagHandle, 0, 2345); // Ok
    var writeStatus = (Status)plctag.plc_tag_write(tagHandle, timeout); // Ok

    WaitUntilNotPending(tagHandle);

    var readStatus = (Status)plctag.plc_tag_read(tagHandle, timeout); // Ok

    WaitUntilNotPending(tagHandle);

    var value = plctag.plc_tag_get_int16(tagHandle, 0);  // 2345
    var status = (Status)plctag.plc_tag_status(tagHandle); // Ok
}

private static void WaitUntilNotPending(int tagHandle)
{
    STATUS_CODES status;
    do status = (STATUS_CODES)plctag.plc_tag_status(tagHandle);
    while (status == STATUS_CODES.PLCTAG_STATUS_PENDING);
    if (status != STATUS_CODES.PLCTAG_STATUS_OK) throw new Exception(status.ToString());
}

private static void eventCallback(int tag_id, int event_id, int status, IntPtr userData)
{
    Console.WriteLine($"____LIBPLCTAG_NET____   {tag_id,-5} | {(Event)event_id,-20} | {(Status)status,-5}");
}

private static void LibPlcTag_LogEvent(object sender, LogEventArgs e)
{
    Console.WriteLine(e.Message);
}

I used the container without any configuration customization, with whatever the defaults they supply are. The container app itself is pretty good I think, it runs in a debug mode by default and shows incoming/outgoing data.

kyle-github commented 1 year ago

That matches the problem that the OP saw. Let me redo this exact example in C and see if I can repeat it. I think the example I converted was using synchronous (waiting) calls.

kyle-github commented 1 year ago

There was definitely a bug here and a hole in my testing. The created event is not raised when creating a tag in async mode. See issue 404 in the core C library.

I have added a couple of tests and fixed (I think) the creation event problem. I have all this in the prerelease branch of the core C library.

I refactored some of the Modbus code to directly generate events within the protocol specific part of the library. This generates all the events that it should both in synchronous and asynchronous mode.

@timyhac can you test the prerelease branch? I want to make sure that this is working before trying a full release.

timyhac commented 1 year ago

@kyle-github - it looks like we're getting the events now.

The way libplctag.NET is implemented is that it waits for a created event with Status=Ok.

The prerelease as it stands triggers one callback with Event=Created and Status=Pending, and so never completes the callback.

To get around this we'd need to poll the status until we get Status=Ok - do you think thats the right way to go?

kyle-github commented 1 year ago

The PLCTAG_EVENT_CREATED event is raised with a status of PLCTAG_STATUS_PENDING when you use async tag creation. That is the actual status as the tag is not fully ready when the handle is returned. If there is an abort, then you get a PLCTAG_EVENT_ABORTED with a status of PLCTAG_ERR_ABORT. You can get non-OK statuses when there is an error for all events.

I will dig into what it would take to return a PLCTAG_EVENT_CREATED once the tag is ready. That only happens when the initial read is done (but this does not work for list or raw tags since they do not do an initial read).

I think we've discussed this before and I thought we'd found a solution. It doesn't seem to be working though.

kyle-github commented 1 year ago

OK. Another attempt in the prerelease branch. I also updated my tests to check whether there are read events coming in before the create finished event, and fail if one is seen.

You should see a created event with a status of OK now. If it is actually OK.

timyhac commented 1 year ago

I think we've discussed this before and I thought we'd found a solution.

I recall discussing things surrounding this topic but not what the solution was.

The updated prerelease looks to be creating the event with Ok now. Looks good! I've only tested the happy path, so I'll try to do some further testing over the next few days in various connectedness scenarios.

I think this has been a good exercise as we've been able to find a few problems both in native library and the wrapper.

One issue that I'm getting now is that, in some situations, the modbus teardown doesn't complete. This only occurs when running a Debug build of the .NET test harness (I'm not sure if the native binary has a debug/release equivalent - I just built the dll using the default CMake configuration). When running the Release build, it does complete. I'm not sure how big of an issue this is, but I did note that there are some users that require a call to shutdown, so this may be important for them.

While it almost never completes when running logging at log level = DETAIL or lower, it does complete about 75% of the time when running at LogLevel = SPEW.

Debug.log Release.log

I'm testing on Windows x86-64

kyle-github commented 1 year ago

Looking at the logs is confusing. I do not see any calls to plc_tag_destroy() or plc_tag_shutdown(). I am not sure why there is any teardown happening unless it is the atexit() stuff (you can hook into program shutdown in POSIX systems and Windows sorta-kinda support that, sometimes). This does bring up that I should hook that to call the new plc_tag_shutdown() instead of just the old shutdown code. The new version of plc_tag_shutdown() tries pretty hard to free up all resources.

kyle-github commented 1 year ago

I tried hooking the POSIX and Windows DLL exit hooks to call plc_tag_shutdown(). It calls it twice (which is fine) when you call it and normally exist after that. The prerelease branch is updated.

This should probably be a new issue.

timyhac commented 1 year ago

This looks to be resolved now - once we're happy with the core library and that is released, I'll update the wrapper packages.

timyhac commented 1 year ago

Hi @nc-koko - could you please try testing with libplctag-v1.1.1-beta.0.

nc-koko commented 1 year ago

@timyhac Async methods are working for me again! Thanks for the fix.

timyhac commented 1 year ago

@nc-koko - Thanks for the feedback and for reporting the issue! We'll leave it as beta for a little while and then release as a non-prerelease

kyle-github commented 1 year ago

Woot! Thanks for calling this to our attention, @nc-koko!

timyhac commented 1 year ago

It has been a couple so will close this issue and release as a production version.