Got AssertionError when receive file

itsucks commented 7 years ago

Hey, I tried to use the latest version, 0.4.4, to transfer files between nova instance and host, mainly instance to host. I've redirected the instance's serial port to host's unix domain socket. On the instance

import serial

ser = serial.Serial(port = '/dev/ttyS2',baudrate=9600,timeout=3)
ser.flushInput()
def getc(size,timeout=1):
    data = ser.read(size)
    return data

def putc(data,timeout=1):
    return ser.write(data)

from xmodem import XMODEM
modem = XMODEM(getc,putc)
test = file('test.txt','rb')
print modem.send(test)
ser.close()

On host

import socket
import sys

if len(sys.argv)!=2:
    print 'usage:python '
unix_socket = sys.argv[1]
s = socket.socket(socket.AF_UNIX, socket.SOCK_STREAM)
s.connect(unix_socket)
def getc(size,timeout=1):
    data = s.recv(size)
    return data

def putc(data,timeout=1):
    return s.send(data)

from xmodem import XMODEM
modem = XMODEM(getc,putc)
test = file('test.txt','wb')
print modem.recv(test)
s.close()

Then I ran these two scripts, the guest send a file and the host try to receive it. But the host constantly got errors and then received the file finally.

root@node-51:~# python receivefile.py /tmp/virtualsocket/0a125fca-efac-4b4d-b681-7c78f3087713 
No handlers could be found for logger "xmodem.XMODEM"
Traceback (most recent call last):
  File "receivefile.py", line 19, in <module>
    print modem.recv(test)
  File "build/bdist.linux-x86_64/egg/xmodem/__init__.py", line 531, in recv
AssertionError: h
root@node-51:~# python receivefile.py /tmp/virtualsocket/0a125fca-efac-4b4d-b681-7c78f3087713 
No handlers could be found for logger "xmodem.XMODEM"
Traceback (most recent call last):
  File "receivefile.py", line 19, in <module>
    print modem.recv(test)
  File "build/bdist.linux-x86_64/egg/xmodem/__init__.py", line 531, in recv
AssertionError:  
root@node-51:~# python receivefile.py /tmp/virtualsocket/0a125fca-efac-4b4d-b681-7c78f3087713 
No handlers could be found for logger "xmodem.XMODEM"
Traceback (most recent call last):
  File "receivefile.py", line 19, in <module>
    print modem.recv(test)
  File "build/bdist.linux-x86_64/egg/xmodem/__init__.py", line 531, in recv
AssertionError:  
root@node-51:~# python receivefile.py /tmp/virtualsocket/0a125fca-efac-4b4d-b681-7c78f3087713 
No handlers could be found for logger "xmodem.XMODEM"
Traceback (most recent call last):
  File "receivefile.py", line 19, in <module>
    print modem.recv(test)
  File "build/bdist.linux-x86_64/egg/xmodem/__init__.py", line 531, in recv
AssertionError:  
root@node-51:~# python receivefile.py /tmp/virtualsocket/0a125fca-efac-4b4d-b681-7c78f3087713 
No handlers could be found for logger "xmodem.XMODEM"
Traceback (most recent call last):
  File "receivefile.py", line 19, in <module>
    print modem.recv(test)
  File "build/bdist.linux-x86_64/egg/xmodem/__init__.py", line 531, in recv
AssertionError:  
root@node-51:~# python receivefile.py /tmp/virtualsocket/0a125fca-efac-4b4d-b681-7c78f3087713 
No handlers could be found for logger "xmodem.XMODEM"
Traceback (most recent call last):
  File "receivefile.py", line 19, in <module>
    print modem.recv(test)
  File "build/bdist.linux-x86_64/egg/xmodem/__init__.py", line 531, in recv
AssertionError:  
root@node-51:~# python receivefile.py /tmp/virtualsocket/0a125fca-efac-4b4d-b681-7c78f3087713 
No handlers could be found for logger "xmodem.XMODEM"
Traceback (most recent call last):
  File "receivefile.py", line 19, in <module>
    print modem.recv(test)
  File "build/bdist.linux-x86_64/egg/xmodem/__init__.py", line 531, in recv
AssertionError:  
root@node-51:~# python receivefile.py /tmp/virtualsocket/0a125fca-efac-4b4d-b681-7c78f3087713 
128
root@node-51:~#

I checked the xmodem/init.py line 531

assert False, data

Did I make a mistake or is this a bug?

jquast commented 7 years ago

Can you provide error?

Anyway I think it's this line, https://github.com/tehmaze/xmodem/blame/master/xmodem/__init__.py#L531

I think I accidentally left this in, I was trying to exercise this line with test coverage and failed or forgot to

jquast commented 7 years ago

I think we both have bugs :(

We should remove this assertion in our code, it is a mistake.

But your code should probably not cause this "PURGE" operation, either!

itsucks commented 7 years ago

But but, after I commented out line 531, both the sender and the receiver got stucked after “No handlers could be found for logger "xmodem.XMODEM”/(ㄒoㄒ)/~~

jquast commented 7 years ago

Thanks for reporting, I did expect some error...

Please suggest: enable debug logging on both sides and share the log output. Thank you!

import logging logging.basicConfig(level=logging.DEBUG)

itsucks commented 7 years ago

I've add LOG on both sides. I ran “python sendfile.py”, and then run “python receivefile.py /tmp/virtualsocket/0a125fca-efac-4b4d-b681-7c78f3087713”. The receiver get the file successful, but the sender didnot stop. And I ran “python receivefile.py /tmp/virtualsocket/0a125fca-efac-4b4d-b681-7c78f3087713” again then it stopped.

The sender

ubuntu@ubuntu:~$ python sendfile.py 
DEBUG:xmodem.XMODEM:Begin start sequence, packet_size=128
DEBUG:xmodem.XMODEM:16-bit CRC requested (CRC).
DEBUG:xmodem.XMODEM:send: block 1
DEBUG:xmodem.XMODEM:send: at EOF
DEBUG:xmodem.XMODEM:sending EOT, awaiting ACK
ERROR:xmodem.XMODEM:send error: expected ACK; got ''
DEBUG:xmodem.XMODEM:sending EOT, awaiting ACK
ERROR:xmodem.XMODEM:send error: expected ACK; got 'C'
DEBUG:xmodem.XMODEM:sending EOT, awaiting ACK
ERROR:xmodem.XMODEM:send error: expected ACK; got 'C'
DEBUG:xmodem.XMODEM:sending EOT, awaiting ACK
ERROR:xmodem.XMODEM:send error: expected ACK; got 'C'
DEBUG:xmodem.XMODEM:sending EOT, awaiting ACK
ERROR:xmodem.XMODEM:send error: expected ACK; got 'C'
DEBUG:xmodem.XMODEM:sending EOT, awaiting ACK
ERROR:xmodem.XMODEM:send error: expected ACK; got 'C'
DEBUG:xmodem.XMODEM:sending EOT, awaiting ACK
ERROR:xmodem.XMODEM:send error: expected ACK; got 'C'
DEBUG:xmodem.XMODEM:sending EOT, awaiting ACK
ERROR:xmodem.XMODEM:send error: expected ACK; got 'C'
DEBUG:xmodem.XMODEM:sending EOT, awaiting ACK
ERROR:xmodem.XMODEM:send error: expected ACK; got 'C'
DEBUG:xmodem.XMODEM:sending EOT, awaiting ACK
ERROR:xmodem.XMODEM:send error: expected ACK; got '\x15'
DEBUG:xmodem.XMODEM:sending EOT, awaiting ACK
ERROR:xmodem.XMODEM:send error: expected ACK; got '\x15'
DEBUG:xmodem.XMODEM:sending EOT, awaiting ACK
ERROR:xmodem.XMODEM:send error: expected ACK; got '\x15'
DEBUG:xmodem.XMODEM:sending EOT, awaiting ACK
ERROR:xmodem.XMODEM:send error: expected ACK; got '\x15'
DEBUG:xmodem.XMODEM:sending EOT, awaiting ACK
ERROR:xmodem.XMODEM:send error: expected ACK; got '\x15'
DEBUG:xmodem.XMODEM:sending EOT, awaiting ACK
ERROR:xmodem.XMODEM:send error: expected ACK; got '\x15'
DEBUG:xmodem.XMODEM:sending EOT, awaiting ACK
ERROR:xmodem.XMODEM:send error: expected ACK; got '\x15'
DEBUG:xmodem.XMODEM:sending EOT, awaiting ACK
ERROR:xmodem.XMODEM:send error: expected ACK; got '\x15'
WARNING:xmodem.XMODEM:EOT was not ACKd, aborting transfer
False

The receiver

root@node-51:~# python receivefile.py /tmp/virtualsocket/0a125fca-efac-4b4d-b681-7c78f3087713 
DEBUG:xmodem.XMODEM:recv: SOH
DEBUG:xmodem.XMODEM:recv: data block 1
INFO:xmodem.XMODEM:Transmission complete, 128 bytes
128
root@node-51:~# python receivefile.py /tmp/virtualsocket/0a125fca-efac-4b4d-b681-7c78f3087713 
DEBUG:xmodem.XMODEM:cancellation at start sequence.
INFO:xmodem.XMODEM:Transmission canceled: received 2xCAN at start-sequence
None

itsucks commented 7 years ago

The process is unstable. Sometimes the sender didnot receive the ACK but there were times it succeed 0.0

itsucks commented 7 years ago

I got it, it's because after I received the file I closed the socket immediately. So the sender couldn't get EOF ACK, I added "time.sleep(1)" then it's ok.But the LOG cannot be removed……

jquast commented 7 years ago

@itsucks "But the LOG cannot be removed....."

I'm not sure what you mean, but let me try to help -- if you want to remove message:

No handlers could be found for logger "xmodem.XMODEM"

Then simply do:

import logging
logging.basicConfig(level=logging.ERROR)

So we have maybe two issues:

This assert False, data line should be removed (and test coverage provided, if possible)
receivefile.py is not always acknowledging EOT (End of Transmission)?

investigating

jquast commented 7 years ago

Ok, @itsucks your problem:

receivefile.py is not always acknowledging EOT (End of Transmission)?

I don't believe to be a problem on our side -- I'm very certain you are not "flushing" data -- that is, waiting for the remote end to receive all bytes that have been sent. a sleep for 1 second isn't perfect, but it serves the same ends.

Hey, by the way, do you know that XMODEM performs "padding" on files to 128-byte blocks?

So if you had a 96-byte .txt file, it would become 128 bytes -- the remaining 32 bytes are "padded" as 32 bytes of b'\x1a' (Ctrl + Z). This is the argument pad to XMODEM initializer.

You might not notice this in your text editor, but it happens. In the old days (CP/M and MS-DOS) ^Z has significance for text files to mean "End of file", and the XMODEM protocol is very old in this regard ...

So... I would recommend you do something out of band to indicate the final size of the file and "trim" away those paddings -- if you wanted to transfer any kind of binary file, it would likely become corrupt, otherwise.

I have branch I will push to resolve this bug, and provide additional test coverage for this "purge" operation. Unfortunately I'm using WIFI on an airplane and SSH isn't working... I'll push and release a 0.5.0 release in a day or two.

rohieb commented 7 years ago

I've just run into this issue with lsz on the sender side and xmodem.recv() on the receiver side. It seems to happen on retransmissions. My getc() and putc() functions both print what they send and receive, and this is what I get on the receiver side:

  DEBUG: XMODEM PUTC: b'C'
  DEBUG: XMODEM GETC(1): read b'\r'
  DEBUG: XMODEM PUTC: b'C'
  DEBUG: XMODEM GETC(1): read b'\n'
  DEBUG: XMODEM PUTC: b'C'
  DEBUG: XMODEM GETC(1): read b'\x01'
  DEBUG: recv: SOH
  DEBUG: recv: data block 1
  DEBUG: XMODEM GETC(1): read b'\x01'
  DEBUG: XMODEM GETC(1): read b'\xfe'
  DEBUG: XMODEM GETC(130): read b'# Network services, Internet style\n#\n# Note that it is presently the policy of IANA to assign a single well-known\n# port number T\x96'
  DEBUG: XMODEM PUTC: b'\x06'
  DEBUG: XMODEM GETC(1): read b'\x01'
  DEBUG: recv: data block 2
  DEBUG: XMODEM GETC(1): read b'\x01'
  DEBUG: XMODEM GETC(1): read b'\xfe'
  ERROR: expected sequence 2, got (seq1=1, seq2=1), receiving next block, will NAK.
  DEBUG: XMODEM GETC(130): read b'# Network services, Internet style\n#\n# Note that it is presently the policy of IANA to assign a single well-known\n# port number T\x96'
WARNING: recv error: purge, requesting retransmission (NAK)
  DEBUG: XMODEM GETC(1): read b'\x01'
Traceback (most recent call last):
  File "test-xmodem.py", line 54, in <module>
    print(command.get("/etc/services", "./test.out"))
  File "/usr/lib/python3.5/site-packages/labgrid-0.1.1.dev1+g0897126.d20170522-py3.5.egg/labgrid/binding.py", line 87, in wrapper
    return func(self, *_args, **_kwargs)
  File "/usr/lib/python3.5/site-packages/labgrid-0.1.1.dev1+g0897126.d20170522-py3.5.egg/labgrid/driver/shelldriver.py", line 293, in get
    self._get(remotefile, localfile)
  File "/usr/lib/python3.5/site-packages/labgrid-0.1.1.dev1+g0897126.d20170522-py3.5.egg/labgrid/step.py", line 192, in wrapper
    _result = func(*_args, **_kwargs)
  File "/usr/lib/python3.5/site-packages/labgrid-0.1.1.dev1+g0897126.d20170522-py3.5.egg/labgrid/driver/shelldriver.py", line 276, in _get
    ret = modem.recv(ofh)
  File "/usr/lib/python3.5/site-packages/xmodem-0.4.4-py3.5.egg/xmodem/__init__.py", line 563, in recv
AssertionError: b'\x01'

The code at xmodem/__init__.py, line 563, as of commit 8897636, looks like this:

551             while True:
552                 # When the receiver wishes to <nak>, it should call a "PURGE"
553                 # subroutine, to wait for the line to clear. Recall the sender
554                 # tosses any characters in its UART buffer immediately upon
555                 # completing sending a block, to ensure no glitches were mis-
556                 # interpreted.  The most common technique is for "PURGE" to
557                 # call the character receive subroutine, specifying a 1-second
558                 # timeout, and looping back to PURGE until a timeout occurs.
559                 # The <nak> is then sent, ensuring the other end will see it.
560                 data = self.getc(1, timeout=1)
561                 if data is None:
562                     break
563                 assert False, data
564             self.putc(NAK)

If I read that comment correctly, the purpose of the while loop here is to throw away everything which is received, in order to empty the UART buffer, and wait until a timeout occurs (if data is None, nothing more is received, i.e. end of the current packet). However, due to the assert, the loop already terminates after the first byte. So I think the assert here should be removed — which I did, and now everything seems to work fine :-) See PR #29 for the (trivial) fix.

That code was introduced in #7 by @jquast, maybe he can say something about it? :-)

jquast commented 7 years ago

This 'asset False' should most definitely be removed, I thought we already have done so. Will investigate, thank you

tehmaze / xmodem

Got AssertionError when receive file #27