[BUG] - 1756-EWEB issue

[tlf30]

Pre-checks

• running latest version
• enabled logging
• consulted the docs

Description
Hello, I am thinking this is an issue in the 1756-EWEB firmware, but wanted to confirm. When opening a forward open connection to an 1756-EWEB, then to the backplane, then back to itself, it fails to close the forward open connection.

This is the easiest situation to replicate this, I have found others, but they are more difficult to replicate. All situations I have found are through the 1756-EWEB and it not closing the forward open connection. My other ethernet modules ENET and ENBT work fine in these situations.

Target PLC
Model: [e.g. 1756-EWEB]
Firmware Revision: 5.1
Other Devices in CIP Path: N/A

Code Sample
Minimal reproduceable code sample

from pycomm3 import CIPDriver, ClassCode, Services, SHORT_STRING
from pycomm3.logger import configure_default_logger, LOG_VERBOSE
configure_default_logger(level=LOG_VERBOSE)


with CIPDriver('192.168.1.12/1/8') as driver:
    resp = driver.generic_message(
        service=Services.get_attribute_single,
        class_code=ClassCode.identity_object,
        instance=1,
        attribute=7,
        connected=True,
        unconnected_send=False,
        data_type=SHORT_STRING,
    )
    print(f'... Got: {resp.value if resp else "EMPTY"}')

C:\Users\tlfal\PycharmProjects\testCipConnections\venv\Scripts\python.exe C:\Users\tlfal\PycharmProjects\testCipConnections\main.py 
2023-05-27 08:34:33,038 [DEBUG] pycomm3.cip_driver.CIPDriver.open(): Opening connection to 192.168.1.12
2023-05-27 08:34:33,041 [VERBOSE] pycomm3.cip_driver.CIPDriver._send(): >>> SEND >>> 
(0000) 65 00 04 00 00 00 00 00 00 00 00 00 5f 70 79 63     e•••••••••••_pyc
(0010) 6f 6d 6d 5f 00 00 00 00 01 00 00 00                 omm_••••••••
2023-05-27 08:34:33,041 [DEBUG] pycomm3.cip_driver.CIPDriver.send(): Sent: RegisterSessionRequestPacket(message=[b'\x01\x00', b'\x00\x00'])
2023-05-27 08:34:33,046 [VERBOSE] pycomm3.cip_driver.CIPDriver._receive(): <<< RECEIVE <<< 
(0000) 65 00 04 00 03 0f 02 11 00 00 00 00 5f 70 79 63     e•••••••••••_pyc
(0010) 6f 6d 6d 5f 00 00 00 00 01 00 00 00                 omm_••••••••
2023-05-27 08:34:33,046 [DEBUG] pycomm3.cip_driver.CIPDriver.send(): Received: RegisterSessionResponsePacket(session=285347587, error=None)
2023-05-27 08:34:33,046 [INFO] pycomm3.cip_driver.CIPDriver._register_session(): Session=285347587 has been registered.
2023-05-27 08:34:33,046 [INFO] pycomm3.cip_driver.wrapped(): Attempting an Extended Forward Open...
2023-05-27 08:34:33,046 [INFO] pycomm3.cip_driver.CIPDriver.generic_message(): Sending generic message: forward_open
2023-05-27 08:34:33,046 [VERBOSE] pycomm3.cip_driver.CIPDriver._send(): >>> SEND >>> 
(0000) 6f 00 44 00 03 0f 02 11 00 00 00 00 5f 70 79 63     o•D•••••••••_pyc
(0010) 6f 6d 6d 5f 00 00 00 00 00 00 00 00 0a 00 02 00     omm_••••••••••••
(0020) 00 00 00 00 b2 00 34 00 5b 02 20 06 24 01 0a 05     ••••••4•[• •$•••
(0030) 00 00 00 00 67 5f 99 75 27 04 09 10 65 d1 b2 d3     ••••g_•u'•••e•••
(0040) 07 00 00 00 01 40 20 00 a0 0f 00 42 01 40 20 00     •••••@ ••••B•@ •
(0050) a0 0f 00 42 a3 03 01 08 20 02 24 01                 •••B•••• •$•
2023-05-27 08:34:33,046 [DEBUG] pycomm3.cip_driver.CIPDriver.send(): Sent: GenericUnconnectedRequestPacket(message=[b'[', b'\x02 \x06$\x01', b"\n\x05\x00\...\x0f\x00B\xa3", b'\x03\x01\x08 \x02$\x01'])
2023-05-27 08:34:33,050 [VERBOSE] pycomm3.cip_driver.CIPDriver._receive(): <<< RECEIVE <<< 
(0000) 6f 00 14 00 03 0f 02 11 00 00 00 00 5f 70 79 63     o•••••••••••_pyc
(0010) 6f 6d 6d 5f 00 00 00 00 00 00 00 00 0a 00 02 00     omm_••••••••••••
(0020) 00 00 00 00 b2 00 04 00 db 00 08 00                 ••••••••••••
2023-05-27 08:34:33,050 [DEBUG] pycomm3.cip_driver.CIPDriver.send(): Received: GenericUnconnectedResponsePacket(service=None, command=b'o\x00', error='Service not supported')
2023-05-27 08:34:33,050 [ERROR] pycomm3.cip_driver.CIPDriver.generic_message(): Generic message 'forward_open' failed: Service not supported
2023-05-27 08:34:33,050 [ERROR] pycomm3.cip_driver.CIPDriver._forward_open(): forward_open failed - Service not supported
2023-05-27 08:34:33,050 [INFO] pycomm3.cip_driver.wrapped(): Extended Forward Open failed, attempting standard Forward Open.
2023-05-27 08:34:33,050 [INFO] pycomm3.cip_driver.CIPDriver.generic_message(): Sending generic message: forward_open
2023-05-27 08:34:33,050 [VERBOSE] pycomm3.cip_driver.CIPDriver._send(): >>> SEND >>> 
(0000) 6f 00 40 00 03 0f 02 11 00 00 00 00 5f 70 79 63     o•@•••••••••_pyc
(0010) 6f 6d 6d 5f 00 00 00 00 00 00 00 00 0a 00 02 00     omm_••••••••••••
(0020) 00 00 00 00 b2 00 30 00 54 02 20 06 24 01 0a 05     ••••••0•T• •$•••
(0030) 00 00 00 00 67 5f 99 75 27 04 09 10 65 d1 b2 d3     ••••g_•u'•••e•••
(0040) 07 00 00 00 01 40 20 00 f4 43 01 40 20 00 f4 43     •••••@ ••C•@ ••C
(0050) a3 03 01 08 20 02 24 01                             •••• •$•
2023-05-27 08:34:33,050 [DEBUG] pycomm3.cip_driver.CIPDriver.send(): Sent: GenericUnconnectedRequestPacket(message=[b'T', b'\x02 \x06$\x01', b"\n\x05\x00\...\x00\xf4C\xa3", b'\x03\x01\x08 \x02$\x01'])
2023-05-27 08:34:33,057 [VERBOSE] pycomm3.cip_driver.CIPDriver._receive(): <<< RECEIVE <<< 
(0000) 6f 00 20 00 03 0f 02 11 00 00 00 00 5f 70 79 63     o• •••••••••_pyc
(0010) 6f 6d 6d 5f 00 00 00 00 00 00 00 00 0a 00 02 00     omm_••••••••••••
(0020) 00 00 00 00 b2 00 10 00 d4 00 01 01 00 01 27 04     ••••••••••••••'•
(0030) 09 10 65 d1 b2 d3 02 00                             ••e•••••
2023-05-27 08:34:33,057 [DEBUG] pycomm3.cip_driver.CIPDriver.send(): Received: GenericUnconnectedResponsePacket(service=None, command=b'o\x00', error='Connection failure (see extended status) - Connection in use  (01, 100)')
2023-05-27 08:34:33,057 [ERROR] pycomm3.cip_driver.CIPDriver.generic_message(): Generic message 'forward_open' failed: Connection failure (see extended status) - Connection in use  (01, 100)
2023-05-27 08:34:33,057 [ERROR] pycomm3.cip_driver.CIPDriver._forward_open(): forward_open failed - Connection failure (see extended status) - Connection in use  (01, 100)
2023-05-27 08:34:33,057 [VERBOSE] pycomm3.cip_driver.CIPDriver._send(): >>> SEND >>> 
(0000) 66 00 00 00 03 0f 02 11 00 00 00 00 5f 70 79 63     f•••••••••••_pyc
(0010) 6f 6d 6d 5f 00 00 00 00                             omm_••••
2023-05-27 08:34:33,057 [DEBUG] pycomm3.cip_driver.CIPDriver.send(): Sent: UnRegisterSessionRequestPacket(message=[])
2023-05-27 08:34:33,057 [DEBUG] pycomm3.cip_driver.CIPDriver.send(): Received: UnRegisterSessionResponsePacket()
2023-05-27 08:34:33,057 [INFO] pycomm3.cip_driver.CIPDriver._un_register_session(): Session Unregistered
2023-05-27 08:34:33,057 [ERROR] pycomm3.cip_driver.CIPDriver.__exit__(): Unhandled Client Error
Traceback (most recent call last):
  File "C:\Users\tlfal\PycharmProjects\testCipConnections\main.py", line 7, in <module>
    resp = driver.generic_message(
  File "C:\Users\tlfal\PycharmProjects\testCipConnections\venv\lib\site-packages\pycomm3\cip_driver.py", line 508, in generic_message
    with_forward_open(lambda _: None)(self)
  File "C:\Users\tlfal\PycharmProjects\testCipConnections\venv\lib\site-packages\pycomm3\cip_driver.py", line 99, in wrapped
    raise ResponseError(msg)
pycomm3.exceptions.ResponseError: Target did not connected. <lambda> will not be executed.
Traceback (most recent call last):
  File "C:\Users\tlfal\PycharmProjects\testCipConnections\main.py", line 7, in <module>
    resp = driver.generic_message(
  File "C:\Users\tlfal\PycharmProjects\testCipConnections\venv\lib\site-packages\pycomm3\cip_driver.py", line 508, in generic_message
    with_forward_open(lambda _: None)(self)
  File "C:\Users\tlfal\PycharmProjects\testCipConnections\venv\lib\site-packages\pycomm3\cip_driver.py", line 99, in wrapped
    raise ResponseError(msg)
pycomm3.exceptions.ResponseError: Target did not connected. <lambda> will not be executed.

Process finished with exit code 1

Additional context
See attached pcap.
eweb.zip

[tlf30]

Oh, it appears when I ran my test to get the output to post here that it simply did not connect this time.
I will get an updated output and capture, one minute.

[tlf30]

OK, I see my confusion.
I am using pycomm3 to verify the results I am seeing with a java cip library.

Let's just start over:
My original issue was as described, and I thought I had replicated the behavior in pycomm3. I no longer think I was able to replicate the behavior though. Pycomm3 fails to make the forward open connection all together (as shown in the output above).

I expected (and was attempting to verify if this behavior is correct) the failure to close the forward open connection that I am seeing in this PCAP:
eweb_failure_to_close.zip

For pycomm3, perhaps the difference is that it is trying to make a large forward open first, but in the java library I am using I explicitly specified to not use large connections. Other than that, I'm not sure why it would fail to connect all together, especially since pycomm3 fails back to a normal connection but still cannot connect.

[ottowayi]

I thin you may be right with attempting the large one first causing the issue. I've seen some weird bugs in these really old modules, specifically certain firmwares on ENET and ENBT modules straight up not supporting required protocol features. It's also possible that the connection parameters for the forward open are causing the problem too. First I would try skipping the large forward open by adding driver._cfg['extended forward open'] = False before calling generic_message and see if that succeeds. If not, we'll have to compare the connection params between your other library and this one to see what the differences are.

edit: another option would be trying without the forward open. e.g.:

with CIPDriver('192.168.1.12') as driver:
    resp = driver.generic_message(
        service=Services.get_attribute_single,
        class_code=ClassCode.identity_object,
        instance=1,
        attribute=7,
        route_path='1/8'
        connected=False,
        unconnected_send=True,
        data_type=SHORT_STRING,
    )
    print(f'... Got: {resp.value if resp else "EMPTY"}')

[tlf30]

Thanks,
I'll play with it some more. I has some attempts a few weeks ago at modifying the config and setting the extend forward open to false, but it kept getting set back. But I will give it another go, maybe I overlooked something.

It may be handy in the future to be able to explicitly set the connection size, and if the connection size is 500 or less not use the large connection.