Closed arma64 closed 4 years ago
plcpeople
commented
4 years ago I will see if I can duplicate this in a test. What version of Node are you using, and on what operating system? I see the log you posted is missing the middle section, is it possible to post the whole log?
arma64
commented
4 years ago OS Ubuntu 14.04.6 LTS Node v12.9.0 nodes7 version:0.3.8 node-red-contrib-s7 version:2.0.2
Log is big. there are part when connection to cpu was interupted: .... [773206,835826052 172.21.105.1 S3] Address DB4503,DW112 has value 7903 and quality OK [773206,835946530 172.21.105.1 S3] Address DB4503,DW116 has value 1073 and quality OK [773206,836081285 172.21.105.1 S3] We are calling back our readDoneCallback. [773806,631232577 172.21.105.1 S3] Reading All Items (readAllItems was called) [773806,631706896 172.21.105.1 S3] Calling SRP from RAI [773806,631943201 172.21.105.1 S3] SendReadPacket called [773806,632398701 172.21.105.1 S3] Sending Read Packet [773806,632648695 172.21.105.1 S3] Sending Read Packet [773806,635304945] We Caught a read/write error ECONNRESET - will DISCONNECT and attempt to reconnect. [773806,635754310 172.21.105.1 S3] ConnectionReset has been called to set the reset as pending [773806,636244534 172.21.105.1 S3] ConnectionReset has been called to set the reset as pending [773808,134114882 172.21.105.1 S3] PacketTimeout called with type read and seq 2 [773808,134467277 172.21.105.1 S3] READ TIMEOUT on sequence number 2 [773808,134645280 172.21.105.1 S3] ReadResponse called [773808,134784550 172.21.105.1 S3] Processing an undefined packet, likely due to timeout error [773808,135091816 172.21.105.1 S3] Timeout error - zero length packet [773808,135542865 172.21.105.1 S3] Received a ZERO RESPONSE Processing Read Packet due to unrecoverable packet error [773808,135677962 172.21.105.1 S3] Processing an undefined packet, likely due to timeout error [773808,135838934 172.21.105.1 S3] Timeout error - zero length packet [773808,135949601 172.21.105.1 S3] Received a ZERO RESPONSE Processing Read Packet due to unrecoverable packet error .... [773808,230667597 172.21.105.1 S3] Received a ZERO RESPONSE Processing Read Packet due to unrecoverable packet error [773808,230785091 172.21.105.1 S3] Time is 0 seconds and 80.2 ms. [773808,230900176 172.21.105.1 S3] SendReadPacket called [773808,231052133 172.21.105.1 S3] PacketTimeout called with type read and seq 9 [773808,231161059 172.21.105.1 S3] READ TIMEOUT on sequence number 9 [773808,231262648 172.21.105.1 S3] ReadResponse called [773808,231380052 172.21.105.1 S3] Processing an undefined packet, likely due to timeout error [773808,231499019 172.21.105.1 S3] Timeout error - zero length packet [773808,231607174 172.21.105.1 S3] Received a ZERO RESPONSE Processing Read Packet due to unrecoverable packet error [773808,231732567 172.21.105.1 S3] Time is 0 seconds and 80.8 ms. [773808,232389353 172.21.105.1 S3] Address PIR1000 has value 0 and quality BAD 255 [773808,232698607 172.21.105.1 S3] Address PIR1004 has value 0 and quality BAD 255 [773808,232898333 172.21.105.1 S3] Address PIR1008 has value 0 and quality BAD 255 ... [773808,276224928 172.21.105.1 S3] Address DB4503,DW116 has value 0 and quality BAD 255 [773808,276347290 172.21.105.1 S3] Calling reset from readResponse as there is one pending [773808,276671062 172.21.105.1 S3] ResetNOW is happening [773808,277302832 172.21.105.1 S3] Connection cleanup is happening [773808,277676317 172.21.105.1 S3] Clearing read PacketTimeouts [773808,278009272 172.21.105.1 S3] Clearing write PacketTimeouts [773808,278742470 172.21.105.1 S3] <initiating a new connection Wed Oct 30 2019 13:17:28 GMT+0200 (Eastern European Standard Time)> [773808,278903856 172.21.105.1 S3] Attempting to connect to host... [773808,279016298 172.21.105.1 S3] We are calling back our readDoneCallback. 30 Oct 13:17:28 - [error] [s7 endpoint:41a1a0ea.14fbb] Failure (Bad values) [773808,283685891 172.21.105.1 S3] TCP Connection Established to 172.21.105.1 on port 102 [773808,283889727 172.21.105.1 S3] Will attempt ISO-on-TCP connection [773808,284118429 172.21.105.1 S3] Using rack [0] and slot [3] [773808,289750762 172.21.105.1 S3] ISO-on-TCP Connection Confirm Packet Received [773808,292490483 172.21.105.1 S3] Received PDU Response - Proceeding with PDU 480 and 2 max parallel connections. [774406,631874203 172.21.105.1 S3] Reading All Items (readAllItems was called) [774406,632365490 172.21.105.1 S3] Calling SRP from RAI [774406,632552739 172.21.105.1 S3] SendReadPacket called [774406,633180769 172.21.105.1 S3] Sending Read Packet [774406,633446003 172.21.105.1 S3] Sending Read Packet [774406,633692993 172.21.105.1 S3] Sending Read Packet [774406,633965926 172.21.105.1 S3] Sending Read Packet [774406,634165675 172.21.105.1 S3] Sending Read Packet [774406,634352563 172.21.105.1 S3] Sending Read Packet [774406,634595995 172.21.105.1 S3] Sending Read Packet [774406,634770149 172.21.105.1 S3] Sending Read Packet [774406,638088264 172.21.105.1 S3] ISO-on-TCP connection DISCONNECTED. [774406,638269148 172.21.105.1 S3] ConnectionReset has been called to set the reset as pending [774406,638544042 172.21.105.1 S3] ConnectionReset has been called to set the reset as pending [774408,133000385 172.21.105.1 S3] PacketTimeout called with type read and seq 2 [774408,133348045 172.21.105.1 S3] READ TIMEOUT on sequence number 2 [774408,133523218 172.21.105.1 S3] ReadResponse called [774408,133645597 172.21.105.1 S3] Processing an undefined packet, likely due to timeout error [774408,133769934 172.21.105.1 S3] Timeout error - zero length packet [774408,133889072 172.21.105.1 S3] Received a ZERO RESPONSE Processing Read Packet due to unrecoverable packet error [774408,133997580 172.21.105.1 S3] Processing an undefined packet, likely due to timeout error [774408,134108802 172.21.105.1 S3] Timeout error - zero length packet ......
there are log when flows restart: ... [774408,271767456 172.21.105.1 S3] Address DB4503,DW112 has value 0 and quality BAD 255 [774408,271834939 172.21.105.1 S3] Address DB4503,DW116 has value 0 and quality BAD 255 [774408,271895923 172.21.105.1 S3] Calling reset from readResponse as there is one pending [774408,271983634 172.21.105.1 S3] ResetNOW is happening [774408,272081911 172.21.105.1 S3] Connection cleanup is happening [774408,272190763 172.21.105.1 S3] Clearing read PacketTimeouts [774408,272268539 172.21.105.1 S3] Clearing write PacketTimeouts [774408,272554974 172.21.105.1 S3] <initiating a new connection Wed Oct 30 2019 13:27:28 GMT+0200 (Eastern European Standard Time)> [774408,272624107 172.21.105.1 S3] Attempting to connect to host... [774408,272690794 172.21.105.1 S3] We are calling back our readDoneCallback. 30 Oct 13:27:28 - [error] [s7 endpoint:41a1a0ea.14fbb] Failure (Bad values) [774408,274355006 172.21.105.1 S3] TCP Connection Established to 172.21.105.1 on port 102 [774408,274435068 172.21.105.1 S3] Will attempt ISO-on-TCP connection [774408,274539133 172.21.105.1 S3] Using rack [0] and slot [3] [774408,280840702 172.21.105.1 S3] ISO-on-TCP Connection Confirm Packet Received [774408,282698372 172.21.105.1 S3] Received PDU Response - Proceeding with PDU 480 and 2 max parallel connections. 30 Oct 13:27:56 - [info] Stopping flows 30 Oct 13:27:56 - [info] [s7 endpoint:41a1a0ea.14fbb] Closing connection to PLC [774436,985564624 172.21.105.1 S3] ISO-on-TCP connection DISCONNECTED. [774436,985767654 172.21.105.1 S3] ConnectionReset has been called to set the reset as pending [774436,985989186 172.21.105.1 S3] ConnectionReset has been called to set the reset as pending 30 Oct 13:27:56 - [info] Stopped flows 30 Oct 13:27:56 - [info] Starting flows 30 Oct 13:27:56 - [info] Started flows 30 Oct 13:27:56 - [info] [s7 endpoint:41a1a0ea.14fbb] Initiating connection to PLC [774437,15518014] Initiate Called - Connecting to PLC with address and parameters: [774437,15697949] { host: '172.21.105.1', port: '102', rack: '0', slot: '3' } [774437,20160011 172.21.105.1 S3] Connection cleanup is happening [774437,20291174 172.21.105.1 S3] Clearing read PacketTimeouts [774437,20424252 172.21.105.1 S3] Clearing write PacketTimeouts [774437,20747102 172.21.105.1 S3] <initiating a new connection Wed Oct 30 2019 13:27:56 GMT+0200 (Eastern European Standard Time)> [774437,20863721 172.21.105.1 S3] Attempting to connect to host... [774437,22901052 172.21.105.1 S3] TCP Connection Established to 172.21.105.1 on port 102 [774437,23090022 172.21.105.1 S3] Will attempt ISO-on-TCP connection [774437,23259505 172.21.105.1 S3] Using rack [0] and slot [3] [774437,27975209 172.21.105.1 S3] ISO-on-TCP Connection Confirm Packet Received [774437,29933129 172.21.105.1 S3] Received PDU Response - Proceeding with PDU 480 and 2 max parallel connections. [774437,30940823] Translation OK [774440,485933978 172.21.105.1 S3] Timed reset has happened. Ideally this would never be called as reset should be completed when done r/w. [774440,486230802 172.21.105.1 S3] ResetNOW is happening [774440,486389585 172.21.105.1 S3] Clearing an earlier scheduled reset [775037,32071331 172.21.105.1 S3] Reading All Items (readAllItems was called) [775037,35384946 172.21.105.1 S3] Adding or Removing { arg: [ 'PM2-L1V', 'PM2-L2V', 'PM2-L3V', 'PM2-L1A', ....... , ... 232 more items ], action: 'add' } [775037,35934964 172.21.105.1 S3] Adding PM2-L1V, .......... ,VAND_HST-FLOW,VAND_FME90-TOT,VAND_FME90-FLOW [775037,67683311 172.21.105.1 S3] Skipping optimization of item PIR1004 [775037,69825385 172.21.105.1 S3] Skipping optimization of item PIR1008 [775037,76061549 172.21.105.1 S3] Skipping optimization of item PIR1012 ... [775037,149957523 172.21.105.1 S3] Skipping optimization of item PIR2108 [775037,150063395 172.21.105.1 S3] Skipping optimization of item DB3504,DW0 [775037,150205709 172.21.105.1 S3] Attempting optimization of item DB3504,DW4 with DB3504,DW0 [775037,150407256 172.21.105.1 S3] Attempting optimization of item DB3504,DW8 with DB3504,DW0 [775037,150589704 172.21.105.1 S3] Attempting optimization of item DB3504,DW12 with DB3504,DW0 ... [775037,159803601 172.21.105.1 S3] Attempting optimization of item DB4503,DW112 with DB4503,DW0 [775037,159916517 172.21.105.1 S3] Attempting optimization of item DB4503,DW116 with DB4503,DW0 [775037,160172649 172.21.105.1 S3] self.globalReadBlockList 0 parts is 1 offset is 1000 MBR is 460 [775037,160475049 172.21.105.1 S3] self.globalReadBlockList 1 parts is 1 offset is 1004 MBR is 460 [775037,160757906 172.21.105.1 S3] self.globalReadBlockList 2 parts is 1 offset is 1008 MBR is 460 [775037,160967897 172.21.105.1 S3] self.globalReadBlockList 3 parts is 1 offset is 1012 MBR is 460 ... [775037,200209485 172.21.105.1 S3] self.globalReadBlockList 253 parts is 1 offset is 0 MBR is 460 [775037,200314192 172.21.105.1 S3] self.globalReadBlockList 254 parts is 1 offset is 0 MBR is 460 [775037,200403445 172.21.105.1 S3] Clearing read PacketTimeouts [775037,200634039 172.21.105.1 S3] Sequence Number is 2 [775037,200779907 172.21.105.1 S3] Splitting request: 39 items, requestLength would be 492, replyLength would be 334, PDU is 480 [775037,200888854 172.21.105.1 S3] Sequence Number is 3 [775037,200987945 172.21.105.1 S3] Splitting request: 39 items, requestLength would be 492, replyLength would be 334, PDU is 480 [775037,201052992 172.21.105.1 S3] Sequence Number is 4 [775037,201147828 172.21.105.1 S3] Splitting request: 39 items, requestLength would be 492, replyLength would be 334, PDU is 480 [775037,201210461 172.21.105.1 S3] Sequence Number is 5 [775037,201302102 172.21.105.1 S3] Splitting request: 39 items, requestLength would be 492, replyLength would be 334, PDU is 480 [775037,201366009 172.21.105.1 S3] Sequence Number is 6 [775037,201455877 172.21.105.1 S3] Splitting request: 39 items, requestLength would be 492, replyLength would be 334, PDU is 480 [775037,201520678 172.21.105.1 S3] Sequence Number is 7 [775037,201608856 172.21.105.1 S3] Splitting request: 39 items, requestLength would be 492, replyLength would be 334, PDU is 480 [775037,201672064 172.21.105.1 S3] Sequence Number is 8 [775037,201750572 172.21.105.1 S3] Splitting request: 20 items, requestLength would be 264, replyLength would be 490, PDU is 480 [775037,201813052 172.21.105.1 S3] Sequence Number is 9 [775037,201875439 172.21.105.1 S3] Calling SRP from RAI [775037,201936369 172.21.105.1 S3] SendReadPacket called [775037,202265093 172.21.105.1 S3] Sending Read Packet [775037,202414020 172.21.105.1 S3] Sending Read Packet [775037,226832276 172.21.105.1 S3] Received 312 bytes of S7-data from PLC. Sequence number is 2 [775037,226950465 172.21.105.1 S3] ReadResponse called [775037,227175939 172.21.105.1 S3] Time is 0 seconds and 25.2 ms. [775037,227253089 172.21.105.1 S3] SendReadPacket called [775037,227365591 172.21.105.1 S3] Sending Read Packet [775037,254315381 172.21.105.1 S3] Received 312 bytes of S7-data from PLC. Sequence number is 3 [775037,254446977 172.21.105.1 S3] ReadResponse called [775037,254620094 172.21.105.1 S3] Time is 0 seconds and 52.2 ms. [775037,254702804 172.21.105.1 S3] SendReadPacket called [775037,254911113 172.21.105.1 S3] Sending Read Packet [775037,277544659 172.21.105.1 S3] Received 312 bytes of S7-data from PLC. Sequence number is 4 [775037,277750920 172.21.105.1 S3] ReadResponse called [775037,278031588 172.21.105.1 S3] Time is 0 seconds and 50.7 ms. [775037,278158425 172.21.105.1 S3] SendReadPacket called [775037,278463689 172.21.105.1 S3] Sending Read Packet [775037,301386235 172.21.105.1 S3] Received 312 bytes of S7-data from PLC. Sequence number is 5 [775037,301546592 172.21.105.1 S3] ReadResponse called [775037,301881581 172.21.105.1 S3] Time is 0 seconds and 47.1 ms. [775037,302010957 172.21.105.1 S3] SendReadPacket called [775037,302260703 172.21.105.1 S3] Sending Read Packet [775037,324307334 172.21.105.1 S3] Received 312 bytes of S7-data from PLC. Sequence number is 6 [775037,324454764 172.21.105.1 S3] ReadResponse called [775037,324734543 172.21.105.1 S3] Time is 0 seconds and 46.4 ms. [775037,324865586 172.21.105.1 S3] SendReadPacket called [775037,325085601 172.21.105.1 S3] Sending Read Packet [775037,348391767 172.21.105.1 S3] Received 312 bytes of S7-data from PLC. Sequence number is 7 [775037,348598400 172.21.105.1 S3] ReadResponse called [775037,348859069 172.21.105.1 S3] Time is 0 seconds and 46.7 ms. [775037,348990567 172.21.105.1 S3] SendReadPacket called [775037,349190988 172.21.105.1 S3] Sending Read Packet [775037,359290144 172.21.105.1 S3] Received 352 bytes of S7-data from PLC. Sequence number is 8 [775037,359450561 172.21.105.1 S3] ReadResponse called [775037,359712928 172.21.105.1 S3] Time is 0 seconds and 34.7 ms. [775037,359841740 172.21.105.1 S3] SendReadPacket called [775037,361066826 172.21.105.1 S3] Received 124 bytes of S7-data from PLC. Sequence number is 9 [775037,361262525 172.21.105.1 S3] ReadResponse called [775037,361457122 172.21.105.1 S3] Time is 0 seconds and 12.4 ms. [775037,361704122 172.21.105.1 S3] Address PIR1000 has value 400.8614807128906 and quality OK [775037,362136927 172.21.105.1 S3] Address PIR1004 has value 398.8785095214844 and quality OK [775037,362307827 172.21.105.1 S3] Address PIR1008 has value 399.2794189453125 and quality OK [775037,362451541 172.21.105.1 S3] Address PIR1012 has value 111.36702728271484 and quality OK
plcpeople
commented
4 years ago Please verify the latest version 0.3.9 resolves the issue. The issue was caused by the code not resetting the number of requests running.
arma64
commented
4 years ago Problem solved! Thank You!
I'm reading a 251 PID and 81 data blocks from SIMATIC S7-400, CPU 414-3 using node-red-contrib-s7. After loosing network connection to CPU, connection reset occurs: [773808,276347290 172.21.105.1 S3] Calling reset from readResponse as there is one pending [773808,276671062 172.21.105.1 S3] ResetNOW is happening [773808,277302832 172.21.105.1 S3] Connection cleanup is happening [773808,277676317 172.21.105.1 S3] Clearing read PacketTimeouts [773808,278009272 172.21.105.1 S3] Clearing write PacketTimeouts [773808,278742470 172.21.105.1 S3] <initiating a new connection Wed Oct 30 2019 13:17:28 GMT+0200 (Eastern European Standard Time)> [773808,278903856 172.21.105.1 S3] Attempting to connect to host... [773808,279016298 172.21.105.1 S3] We are calling back our readDoneCallback. 30 Oct 13:17:28 - [error] [s7 endpoint:41a1a0ea.14fbb] Failure (Bad values) [773808,283685891 172.21.105.1 S3] TCP Connection Established to 172.21.105.1 on port 102 [773808,283889727 172.21.105.1 S3] Will attempt ISO-on-TCP connection [773808,284118429 172.21.105.1 S3] Using rack [0] and slot [3] [773808,289750762 172.21.105.1 S3] ISO-on-TCP Connection Confirm Packet Received [773808,292490483 172.21.105.1 S3] Received PDU Response - Proceeding with PDU 480 and 2 max parallel connections
But after that read timeout: [774406,631874203 172.21.105.1 S3] Reading All Items (readAllItems was called) [774406,632365490 172.21.105.1 S3] Calling SRP from RAI [774406,632552739 172.21.105.1 S3] SendReadPacket called [774406,633180769 172.21.105.1 S3] Sending Read Packet [774406,633446003 172.21.105.1 S3] Sending Read Packet [774406,633692993 172.21.105.1 S3] Sending Read Packet [774406,633965926 172.21.105.1 S3] Sending Read Packet [774406,634165675 172.21.105.1 S3] Sending Read Packet [774406,634352563 172.21.105.1 S3] Sending Read Packet [774406,634595995 172.21.105.1 S3] Sending Read Packet [774406,634770149 172.21.105.1 S3] Sending Read Packet [774406,638088264 172.21.105.1 S3] ISO-on-TCP connection DISCONNECTED. [774406,638269148 172.21.105.1 S3] ConnectionReset has been called to set the reset as pending [774406,638544042 172.21.105.1 S3] ConnectionReset has been called to set the reset as pending [774408,133000385 172.21.105.1 S3] PacketTimeout called with type read and seq 2
on tcpdump i found that read var pdus now are in one tcp packet (before each pdu was in different tcp packet): Frame 51: 1514 bytes on wire (12112 bits), 1514 bytes captured (12112 bits) Ethernet II, Src: Vmware_42:95:e9 (00:0c:29:42:95:e9), Dst: Routerbo_ed:92:c0 (6c:3b:6b:ed:92:c0) Internet Protocol Version 4, Src: 192.168.0.201, Dst: 172.21.105.1 Transmission Control Protocol, Src Port: 43574, Dst Port: 102, Seq: 535, Ack: 50, Len: 1460 TPKT, Version: 3, Length: 487 ISO 8073/X.224 COTP Connection-Oriented Transport Protocol S7 Communication Header: (Job) Protocol Id: 0x32 ROSCTR: Job (1) Redundancy Identification (Reserved): 0x0000 Protocol Data Unit Reference: 3 Parameter length: 470 Data length: 0 Parameter: (Read Var) TPKT, Version: 3, Length: 487 ISO 8073/X.224 COTP Connection-Oriented Transport Protocol S7 Communication Header: (Job) Protocol Id: 0x32 ROSCTR: Job (1) Redundancy Identification (Reserved): 0x0000 Protocol Data Unit Reference: 4 Parameter length: 470 Data length: 0 Parameter: (Read Var)
If i restarting flows all readings are ok.
Where to dig? :)