WIZ145SR internal buffer overwrite

fdkz · March 31, 2014, 3:37pm

Hi,

The situation seems to be that sometimes packets sent to WIZ145SR (firmware 1.6.1) from ethernet will be written into the middle of the packets coming in from the serial port. Baud rate is 115200, WIZ145SR is configured as a tcp server and at the moment we’re sending data only through one serial port. Data rate is about 5kB/s, max 10kB/s. Overwrites occur maybe once per 2-10 minutes. We’ve observed the same behaviour with two (all we have at the moment) WIZ145SR modules.

For example, listening physically on the serial port rx line gives us this packet entering the wiznet module:

2014-03-31 16:49:25.85 85 bytes:
7ee3b283 03006c03 22484da7 311c6d1a aa4adfa3 75fce883 c6f0cec1 2de3d6b5 5c9fb9a3 e8b79aae ec7fb8b5 b2bafebb 363ecbe0 7f89d393 dd7c7d33 716f8fa3 3d68447c 7372a3ec ff000dbc 6cddbfd3 eded6cf6 7e

sudo tcpdump src 192.168.2.45 -x
gives us this same packet coming out of the wiznet module:

16:49:25.852130
7ee3b283 03006c03 22484da7 311c6d1a aa4adfa3 7edef685 e33c7e3c 2de3d6b5 5c9fb9a3 e8b79aae ec7fb8b5 b2bafebb 363ecbe0 7f89d393 dd7c7d33 716f8fa3 3d68447c 7372a3ec ff000dbc 6cddbfd3 eded6cf6 7e

The difference is “7edef685 e33c7e” in the middle of the tcp-dumped packet. This exact 7-byte packet is sent by our application once per second to the wiznet ethernet port in order to be forwarded to the serial port. But now it comes back out of the ethernet port while destroying some data.

Has anyone experienced something similar? I’d be happy to help debug the problem.

For reference, here’s the real tcpdump output of the packet under investigation with tcp/ip headers:

[code]sudo tcpdump src 192.168.2.45 -x

16:49:25.840483 IP 192.168.2.45.50001 > 192.168.2.61.56122: Flags [P.], seq 48808:48809, ack 1333, win 8190, length 1
0x0000: 4500 0029 0717 4000 8006 6dfd c0a8 022d
0x0010: c0a8 023d c351 db3a 74d2 323f a03a 5618
0x0020: 5018 1ffe 5021 0000 7e00 0000 0000
16:49:25.843147 IP 192.168.2.45.50001 > 192.168.2.61.56122: Flags [.], ack 1340, win 8180, length 0
0x0000: 4500 0028 0718 4000 8006 6dfd c0a8 022d
0x0010: c0a8 023d c351 db3a 74d2 3240 a03a 561f
0x0020: 5010 1ff4 ce2c 0000 0000 0000 0000
16:49:25.852130 IP 192.168.2.45.50001 > 192.168.2.61.56122: Flags [P.], seq 48809:48893, ack 1340, win 8190, length 84
0x0000: 4500 007c 0719 4000 8006 6da8 c0a8 022d
0x0010: c0a8 023d c351 db3a 74d2 3240 a03a 561f
0x0020: 5018 1ffe ebe3 0000 e3b2 8303 006c 0322
0x0030: 484d a731 1c6d 1aaa 4adf a37e def6 85e3
0x0040: 3c7e 3c2d e3d6 b55c 9fb9 a3e8 b79a aeec
0x0050: 7fb8 b5b2 bafe bb36 3ecb e07f 89d3 93dd
0x0060: 7c7d 3371 6f8f a33d 6844 7c73 72a3 ecff
0x0070: 000d bc6c ddbf d3ed ed6c f67e[/code]

javakys · April 4, 2014, 12:21am

Hi,
I’m James from WIZnet and I’m a developer of WIZ145SR.
WIZ145SR did have some fault for handling data buffer by Ver1.4x.
Firmware ver 1.6.1 handle internal data buffer with strict separation.
I’ll look through my code deeply.
Please wait for a few days.

Thank you.

James.

javakys · April 28, 2014, 11:12pm

Hello,

How about testing with the latest firmware and configuration tool which I uploaded last week?
Please refer to [url][Notice]Latest FW and Configuration Tool]

Thank you.

James

fdkz · September 8, 2014, 2:06pm

Hi,

I was not able to work on the wiznet hardware for the past few months, but I’m on it again. This time with another WIZ145SR device (firmware is 1.6.3), but the buf overwrite problem persists. I’ve written two simple python scripts to test it:

wiz_serial.py

[code]
import serial
import sys

PORT = “/dev/ttyUSB0”
BAUD = 115200
rxtx_period = 0.2

port = serial.Serial(PORT, BAUD, timeout=rxtx_period) # port 1 of the WZ145SR
count = 0

while 1:
# send “0001_abcdef…z\n”
tx = “%04i_” % count + ‘’.join([chr(i) for i in range(ord(“a”), ord(“z”) + 1)]) + “\n”
port.write(tx)

rx = port.read(4096)
if rx: sys.stdout.write(rx)

count += 1[/code]

wiz_tcp.py

import socket
import time
import sys


HOST = "192.168.1.100"
PORT = 50001
rxtx_period = 0.2


s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
s.connect((HOST, PORT))
count = 0

while 1:
	# send "0001_ABCDEF...Z\n"
	tx =  "%04i_" % count + ''.join([chr(i) for i in range(ord("A"), ord("Z") + 1)]) + "\n"
	s.sendall(tx)

	rx = s.recv(4096)
	if rx: sys.stdout.write(rx)

	count += 1
	time.sleep(rxtx_period)

One scipt sends out lines with small letters, the other with capital letters. Both scripts print what they receive. By default, both scripts send out lines with 0.2 s period. The overwrite errors occur multiple times per minute and even with lower data rates.

Example of an error:

...
0083_abcdefghijklmnopqrstuvwxyz
0084_abcdefghijklmnopqrstuvwxyz
0085_abcdefghijkLMNOPQRSTUVWXYZ
0086_abcdefghijklmnopqrstuvwxyz
0087_abcdefghijklmnopqrstuvwxyz
...
...
0091_ABCDEFGHIJKLMNOPQRSTUVWXYZ
0092_ABCDEFGHIJKLMNOPQRSTUVWXYZ
0069_abcDEFGHIJKLMNOPQRSTUVWXYZ
0094_ABCDEFGHIJKLMNOPQRSTUVWXYZ
0095_ABCDEFGHIJKLMNOPQRSTUVWXYZ
...

javakys · September 30, 2014, 12:13am

Hello,

I understood what your test environment is now.
Thank you.

I’ll test and examine your problem.

Please wait for a few days. I will come back and answer you soon.
Thank you.

James.

javakys · September 30, 2014, 1:36am

Hello,

I encountered the symptom which you mentioned during my test.
After debugging, I found what made this problem.
It came from buffer overlap as everyone can imagine.

I added temporary buffers to support telnet mode.
But I didn’t move serial buffer’s address and it made this problem.

I’m sorry that you suffer from my fault.

Please download and test the latest firmware, Ver 1.6.4 on [url][Notice]Latest FW and Configuration Tool]

If you have any problem, please leave a message here.

Thank you.

James.

fdkz · September 30, 2014, 4:51pm

Hi, no more errors with the new firmware. Thanks : )

javakys · September 30, 2014, 10:28pm

I’m pleased to hear your good result.

Thank you.

James.

fdkz · March 25, 2015, 4:02pm

Hi,

Sorry to say but we’ve found some more errors. Right now there seem to be 3 separate problems.

Occasionally some of the buffer gets replayed in the serial->ethernet direction.
Quite often the last byte of a packet gets stuck in the serial->ethernet direction until at least one more byte is sent in the same direction. That starts to happens after a quick burst of data in the same direction.
This one is harder to pin down. After about a week of running, bytes start to go missing on the ethernet->serial direction. The application we had sent ~7-byte packets every second, and some bytes were missing from almost every packet. I hope it’s somehow connected with the previous bugs, or that I can get a better log of what’s happening when I see it the next time.

Problem 1 demonstration scripts:
wiz_serial.py

[code]import logging
log = logging.getLogger(name)
logging.basicConfig(level=logging.NOTSET, format=“%(asctime)s: %(message)s”)
import time, serial

count = 0
port = serial.Serial(“/dev/tty.SLAB_USBtoUART”, 115200, timeout=0.01)

while 1:
tx = “%04i_abcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyz_%04i\n” % (count, count)
port.write(tx)

rx = port.read(4096)
if rx: log.info("rx: %s", repr(rx))

count += 1
time.sleep(0.1)

[/code]

wiz_tcp.py

[code]import logging
log = logging.getLogger(name)
logging.basicConfig(level=logging.NOTSET, format=“%(asctime)s: %(message)s”)
import time, socket

s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
s.connect((“192.168.2.46”, 50001))
count = 0

while 1:
#tx = “%04i_ABCDEFGHIJKLMNOPQRSTUVWXYZABCDEFGHIJKLMNOPQRSTUVWXYZABCDEFGHIJKLMNOPQRSTUVWXYZ_%04i\n” % (count, count)
#s.sendall(tx)

rx = s.recv(4096) # blocking read
if rx: log.info("rx: %s", repr(rx))

count += 1
time.sleep(0.1)

[/code]

Problem 1 log example:

2015-03-25 17:51:19,281: rx: '0231_abcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyz_0231' 2015-03-25 17:51:19,386: rx: '\n0232_abcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyz_0232' 2015-03-25 17:51:19,489: rx: '\n0233_abcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyz_0233\n' 2015-03-25 17:51:19,593: rx: '0234_abcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyz_0234\n' 2015-03-25 17:51:19,694: rx: '0235_abcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyz_0235\n' 2015-03-25 17:51:19,795: rx: '0236_abcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyz_0236\n' 2015-03-25 17:51:19,897: rx: '0237_abcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyz_0237' 2015-03-25 17:51:20,003: rx: '\n0238_abcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrsqrstuvwxyz_0232\n0233_abcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyz_0233\n0234_abcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyz_0234\n0235_abcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyz_0235\n0236_abcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyz_0236\n0237_abcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyz_0237\n0238_abcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyz_0238\n' 2015-03-25 17:51:20,108: rx: '0239_abcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyz_0239'
Problem 2 demonstration scripts:

wiz_serial.py

[code]import logging
log = logging.getLogger(name)
logging.basicConfig(level=logging.NOTSET, format=“%(asctime)s: %(message)s”)
import time, serial

count = 0
port = serial.Serial(“/dev/tty.SLAB_USBtoUART”, 115200, timeout=0.01)
port.write(“=”*100000) # send a 100kB burst

while 1:
tx = “%04i_abcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyz_%04i\n” % (count, count)
port.write(tx)

rx = port.read(4096)
if rx: log.info("rx: %s", repr(rx))

count += 1
time.sleep(1.)

[/code]

wiz_tcp.py

[code]import logging
log = logging.getLogger(name)
logging.basicConfig(level=logging.NOTSET, format=“%(asctime)s: %(message)s”)
import time, socket

s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
s.connect((“192.168.2.46”, 50001))
count = 0

while 1:
rx = s.recv(4096) # blocking read
if rx: log.info(“rx: %s”, repr(rx))

count += 1
time.sleep(0.01)[/code]

Problem 2 log example: (note that the “\n” comes one second late)

2015-03-25 17:41:18,261: rx: '00' 2015-03-25 17:41:18,274: rx: '09_abcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyz_0009' 2015-03-25 17:41:19,278: rx: '\n0'

javakys · March 26, 2015, 7:27am

OK. I’ll check it again.
And I’ll wait for your detail captured log.

Thank you.

javakys.

fdkz · March 30, 2015, 3:39pm

Hi, at the moment it seems with very high probability that problem 3 is not a fault of wiznet, but my own problem. Problems 1 and 2 remain.
Good luck.

Topic		Replies	Views
[From QnA] WIZ140SR at 115200 baud WIZ14xSR	1	685	September 9, 2013
Major Data Latency Bug in WIZ108SR Firmware v4.05 WIZ107/108SR	0	637	May 25, 2016
Lost bytes with Wiz 107SR WIZ107/108SR	1	617	November 10, 2014
[From QnA] Problem in using WIZ145SR WIZ14xSR	2	754	September 9, 2013
Wiz108 sr server mode problem WIZ107/108SR	4	1171	February 24, 2017

WIZ145SR internal buffer overwrite

Related Topics