Cisco IOS uploads to ptftpd fail with "File already exists error"

[mpenning]

FYI, I tried to use ptftpd under python 2.6.6, running as root to receive a configuration file from Cisco IOS. When the switch sent the first UDP packet to port 69, ptftpd started opening the new file to receive the config, but never sent a tftp response packet.

When Cisco IOS retried four seconds later, ptftpd responded that the file already exists, and that killed the tftp session.

Is there anything else I can do to help fix this issue?

[mpetazzoni]

Can you run the server in debug mode and show me what it outputs? Also, did you try running in strict RFC1350 mode (with -r)?

[mpenning]

The problem exists with and without -r... I am including a traceback and the output with -D...

INFO(tftpd): Serving TFTP requests on eth0:69 in /home/mpenning
INFO(tftpd): Upload of test.conf began.
----------------------------------------
Exception happened during processing of request from ('10.19.255.41', 52116)
Traceback (most recent call last):
  File "/usr/lib64/python2.6/SocketServer.py", line 293, in _handle_request_noblock
    self.process_request(request, client_address)
  File "/usr/lib64/python2.6/SocketServer.py", line 319, in process_request
    self.finish_request(request, client_address)
  File "/usr/lib64/python2.6/SocketServer.py", line 332, in finish_request
    self.RequestHandlerClass(request, client_address, self)
  File "/usr/lib64/python2.6/SocketServer.py", line 627, in __init__
    self.handle()
  File "/opt/virtual_env/py26_default/lib/python2.6/site-packages/ptftplib/tftpserver.py", line 108, in handle
    response = handler(opcode, request[2:])
  File "/opt/virtual_env/py26_default/lib/python2.6/site-packages/ptftplib/tftpserver.py", line 266, in serveWRQ
    return self.finish_state(peer_state)
  File "/opt/virtual_env/py26_default/lib/python2.6/site-packages/ptftplib/tftpserver.py", line 115, in finish_state
    return peer_state.next()
  File "/opt/virtual_env/py26_default/lib/python2.6/site-packages/ptftplib/state.py", line 177, in next
    return self.__next_recv()
  File "/opt/virtual_env/py26_default/lib/python2.6/site-packages/ptftplib/state.py", line 229, in __next_recv
    data_len = len(self.data)
TypeError: object of type 'NoneType' has no len()
----------------------------------------
WARNING(tftpd): Client attempted to overwrite file test.conf!
DEBUG(tftpd): Removed stale peer 10.19.255.41:52116.

[mpetazzoni]

Thanks for your reply. Can you apply the following patch to help me debug your situation further? It will enable full protocol logging:

diff --git a/ptftplib/proto.py b/ptftplib/proto.py
index 4a5fb84..517ac16 100644
--- a/ptftplib/proto.py
+++ b/ptftplib/proto.py
@@ -24,10 +24,10 @@ l = notify.getLogger('tftp-proto')
 notify.NullEngine.install(l)

 # Uncomment these lines to enable full protocol dump.
-# import sys
-# import logging
-#
-# notify.StreamEngine.install(l, sys.stderr, logging.DEBUG)
+import sys
+import logging
+
+notify.StreamEngine.install(l, sys.stderr, logging.DEBUG)

 # The following values are defined in the following RFC documents:
 #   - RFC1350 - The TFTP Protocol (revision 2)

Once you've applied it (patch -p1 diff), run the server again in debug mode with -D and give me the log output. It will help me figure out at what point exactly the server encounters the bug.

Thanks!

[mpenning]

Apologies for the delay... I patched as you requested, this is what I got when I tried to copy a cisco nexus 7000 configuration to the python tftpd...

myHost:~ % sudo /user/REDACTED/RHEL6/bin/ptftpd -D eth0 /user/REDACTED

                                               [Executed at 2016-08-15 10:08:46]
INFO(tftpd): Serving TFTP requests on eth0:69 in /user/REDACTED
  <   WRQ: SWITCHNAME-running-config (mode: octet, opts: {})
INFO(tftpd): Upload of SWITCHNAME-running-config began.
----------------------------------------
Exception happened during processing of request from ('192.0.2.1', 40721)
Traceback (most recent call last):
  File "/project/common/prefix/2/RHEL6/lib/python2.7/SocketServer.py", line 295, in _handle_request_noblock
    self.process_request(request, client_address)
  File "/project/common/prefix/2/RHEL6/lib/python2.7/SocketServer.py", line 321, in process_request
    self.finish_request(request, client_address)
  File "/project/common/prefix/2/RHEL6/lib/python2.7/SocketServer.py", line 334, in finish_request
    self.RequestHandlerClass(request, client_address, self)
  File "/project/common/prefix/2/RHEL6/lib/python2.7/SocketServer.py", line 655, in __init__
    self.handle()
  File "/user/REDACTED/RHEL6/lib/python2.7/site-packages/ptftplib/tftpserver.py", line 108, in handle
    response = handler(opcode, request[2:])
  File "/user/REDACTED/RHEL6/lib/python2.7/site-packages/ptftplib/tftpserver.py", line 266, in serveWRQ
    return self.finish_state(peer_state)
  File "/user/REDACTED/RHEL6/lib/python2.7/site-packages/ptftplib/tftpserver.py", line 115, in finish_state
    return peer_state.next()
  File "/user/REDACTED/RHEL6/lib/python2.7/site-packages/ptftplib/state.py", line 177, in next
    return self.__next_recv()
  File "/user/REDACTED/RHEL6/lib/python2.7/site-packages/ptftplib/state.py", line 229, in __next_recv
    data_len = len(self.data)
TypeError: object of type 'NoneType' has no len()
----------------------------------------
  <   WRQ: SWITCHNAME-running-config (mode: octet, opts: {})
WARNING(tftpd): Client attempted to overwrite file SWITCHNAME-running-config!
  > ERROR: 6 File already exists.

[mpetazzoni]

Could you try the just-released version 1.2? It contains a fix for handling of WRQ requests.