TFTP; Datagram received with wrong TID with Cisco 7940 SIP

Added by Tim Waite 3 months ago

System:
Wazo 17.07 on Debian 8.8 hosted on Vmware ESXi 6

Phone:
Cisco 7940 with SIP image

Provd Script:
zero

Issue:
When phone requests TFTP file from server, a "(provd.servers.tftp.connection): Datagram received with wrong TID" appears in the /var/log/xivo-provd.log file
Phone can not get SIP00127Fxxxxxx.cnf file when this happens.

Phone is on local subnet not behind NAT. Other SCCP phones CAN get the proper files that use xivo-cisco-sccp-legacy.

7940 SIP phone can get TFTP SIP00127Fxxxxxx.cnf configuration files from another TFTP server in the network when I have the DHCP options to get the file from the other server.

Issue:
It appears that the dynamic ports setup between the TFTP client and server are not correct and generate this TID error. Why and how I do not know. I did get this to work once after a reboot of the VOIP server but that does not always cure the problem.

More Log Data:

2017-06-05 13:29:49,816 [1121] (INFO) (provd.devices.ident): <14> Extracted device info: {u'ip': u'192.168.xxx.xxx', u'mac': u'00:12:7f:xx:xx:xx', u'vendor': u'Cisco'}
2017-06-05 13:29:49,816 [1121] (INFO) (provd.devices.ident): <14> Retrieved device id: 14931e72bab74b7e82853bee31bd3120
2017-06-05 13:29:49,816 [1121] (INFO) (provd.devices.ident): <14> Routing request to plugin zero
2017-06-05 13:29:49,817 [1121] (INFO) (provd.servers.tftp.proto): TFTP read request rejected: File not found
2017-06-05 13:29:49,871 [1121] (INFO) (provd.servers.tftp.proto): TFTP read request from ('192.168.xxx.xxx', 50179)
2017-06-05 13:29:49,871 [1121] (INFO) (provd.devices.ident): Processing TFTP request: SIP00127Fxxxxxx.cnf
2017-06-05 13:29:49,872 [1121] (INFO) (provd.devices.ident): <15> Extracted device info: {u'ip': u'192.168.xxx.xxx'}
2017-06-05 13:29:49,872 [1121] (INFO) (provd.devices.ident): <15> Retrieved device id: 14931e72bab74b7e82853bee31bd3120
2017-06-05 13:29:49,873 [1121] (INFO) (provd.devices.ident): <15> Routing request to plugin zero
2017-06-05 13:29:49,873 [1121] (INFO) (provd.servers.tftp.proto): TFTP read request accepted
2017-06-05 13:29:49,873 [1121] (INFO) (twisted): RFC1350Connection starting on 34617
2017-06-05 13:29:49,873 [1121] (INFO) (twisted): Starting protocol <provd.servers.tftp.connection.RFC1350Connection instance at 0x7ff7dfb33050>
2017-06-05 13:29:49,910 [1121] (INFO) (provd.servers.tftp.connection): Datagram received with wrong TID

ANY IDEAS??

Thanks!

Tim


Replies (6)

RE: TFTP; Datagram received with wrong TID with Cisco 7940 SIP - Added by Sylvain Boily 3 months ago

Hello,

Do you have nat in your architecture? tftp and nat is not friendly. You need to enabled tftp nat kernel module.

RE: TFTP; Datagram received with wrong TID with Cisco 7940 SIP - Added by Tim Waite 3 months ago

Not. This is not going over NAT as stated... I know TFTP and NAT don't like each other.

Thanks

RE: TFTP; Datagram received with wrong TID with Cisco 7940 SIP - Added by Sylvain Boily 3 months ago

Have you try a tcpdump?
Maybe https://tools.ietf.org/html/rfc783 can help to understand this issue. It's not possible to use http instead tftp?

RE: TFTP; Datagram received with wrong TID with Cisco 7940 SIP - Added by Tim Waite 3 months ago

Older Cisco only support TFTP. I had reviewed that RFC and a few more. It looks like the phone and the TFTP server dont have the same port set when transferring data. That is how it appears to me while reviewing the code for that error message on Wazo server. This should just work and I have other SCCP devices and non Cisco TFTP working fine. It is ONLY the SIP 7940 phones that give this error message.

RE: TFTP; Datagram received with wrong TID with Cisco 7940 SIP - Added by Tim Waite 3 months ago

BTW the RFC for TFTP that should be used and was used by Twisted is RFC1350 from my understanding.

https://tools.ietf.org/html/rfc1350

This obsoletes: RFC 783

Tim

RE: TFTP; Datagram received with wrong TID with Cisco 7940 SIP - Added by Tim Waite 3 months ago

Here is a TCP with a log file. This is also not occurring with SCCP clients too... I tried another reboot.. no good. There is not NAT. I can use another TFTP server and redirect everything to that and it works. It is the server in Wazo that appears to be the issue.

23:54:26.568320 IP 192.168.122.119.50006 > 192.168.249.225.tftp: 32 RRQ "SEP000Fxxxxxxxx.cnf.xml" octet
23:54:26.568482 IP 192.168.122.119.50007 > 192.168.249.225.tftp: 21 RRQ "RINGLIST.XML" octet
23:54:26.571117 IP 192.168.249.225.37021 > 192.168.122.119.50006: UDP, length 516
23:54:26.572748 IP 192.168.249.225.47638 > 192.168.122.119.50007: UDP, length 51
23:54:26.609412 IP 192.168.122.119.1509 > 192.168.249.225.37021: UDP, length 4
23:54:26.609685 IP 192.168.249.225.37021 > 192.168.122.119.1509: UDP, length 16
23:54:26.610959 IP 192.168.122.119.1509 > 192.168.249.225.47638: UDP, length 4
23:54:26.611171 IP 192.168.249.225.47638 > 192.168.122.119.1509: UDP, length 16
23:54:26.643193 IP 192.168.122.119.50008 > 192.168.249.225.tftp: 32 RRQ "DISTINCTIVERINGLIST.XML" octet
23:54:26.644956 IP 192.168.249.225.59416 > 192.168.122.119.50008: UDP, length 51
23:54:26.739715 IP 192.168.122.119.1509 > 192.168.249.225.59416: UDP, length 4
23:54:26.740122 IP 192.168.249.225.59416 > 192.168.122.119.1509: UDP, length 16
23:54:30.571600 IP 192.168.249.225.37021 > 192.168.122.119.50006: UDP, length 516
23:54:30.572888 IP 192.168.249.225.47638 > 192.168.122.119.50007: UDP, length 51
23:54:30.645233 IP 192.168.249.225.59416 > 192.168.122.119.50008: UDP, length 51
23:54:34.572351 IP 192.168.249.225.37021 > 192.168.122.119.50006: UDP, length 516
23:54:34.573035 IP 192.168.249.225.47638 > 192.168.122.119.50007: UDP, length 51
23:54:34.645455 IP 192.168.249.225.59416 > 192.168.122.119.50008: UDP, length 51
23:54:38.572954 IP 192.168.249.225.37021 > 192.168.122.119.50006: UDP, length 516
23:54:38.573216 IP 192.168.249.225.47638 > 192.168.122.119.50007: UDP, length 51
23:54:38.645702 IP 192.168.249.225.59416 > 192.168.122.119.50008: UDP, length 51

2017-06-06 23:54:26,568 [1213] (INFO) (provd.servers.tftp.proto): TFTP read request from ('192.168.122.119', 50006)
2017-06-06 23:54:26,568 [1213] (INFO) (provd.devices.ident): Processing TFTP request: SEP000Fxxxxxxxx.cnf.xml
2017-06-06 23:54:26,569 [1213] (INFO) (provd.devices.ident): <33> Extracted device info: {u'ip': u'192.168.122.119', u'mac': u'00:0f:xx:xx:xx:xx', u'vendor': u'Cisco'}
2017-06-06 23:54:26,569 [1213] (INFO) (provd.devices.ident): <33> Retrieved device id: 0c28ba1a9dd24fe188253ea4ad6b54e1
2017-06-06 23:54:26,570 [1213] (INFO) (provd.devices.ident): <33> Routing request to plugin xivo-cisco-sccp-legacy
2017-06-06 23:54:26,570 [1213] (INFO) (provd.security): Sensitive file requested from 192.168.122.119: SEP000Fxxxxxxxx.cnf.xml
2017-06-06 23:54:26,570 [1213] (INFO) (provd.servers.tftp.proto): TFTP read request accepted
2017-06-06 23:54:26,570 [1213] (INFO) (twisted): RFC1350Connection starting on 37021
2017-06-06 23:54:26,570 [1213] (INFO) (twisted): Starting protocol <provd.servers.tftp.connection.RFC1350Connection instance at 0x7ff268b0efc8>
2017-06-06 23:54:26,571 [1213] (INFO) (provd.servers.tftp.proto): TFTP read request from ('192.168.122.119', 50007)
2017-06-06 23:54:26,571 [1213] (INFO) (provd.devices.ident): Processing TFTP request: RINGLIST.XML
2017-06-06 23:54:26,571 [1213] (INFO) (provd.devices.ident): <34> Extracted device info: {u'ip': u'192.168.122.119'}
2017-06-06 23:54:26,571 [1213] (INFO) (provd.devices.ident): <34> Retrieved device id: 0c28ba1a9dd24fe188253ea4ad6b54e1
2017-06-06 23:54:26,572 [1213] (INFO) (provd.devices.ident): <34> Routing request to plugin xivo-cisco-sccp-legacy
2017-06-06 23:54:26,572 [1213] (INFO) (provd.servers.tftp.proto): TFTP read request accepted
2017-06-06 23:54:26,572 [1213] (INFO) (twisted): RFC1350Connection starting on 47638
2017-06-06 23:54:26,572 [1213] (INFO) (twisted): Starting protocol <provd.servers.tftp.connection.RFC1350Connection instance at 0x7ff268aafa70>
2017-06-06 23:54:26,609 [1213] (INFO) (provd.servers.tftp.connection): Datagram received with wrong TID
2017-06-06 23:54:26,611 [1213] (INFO) (provd.servers.tftp.connection): Datagram received with wrong TID
2017-06-06 23:54:26,643 [1213] (INFO) (provd.servers.tftp.proto): TFTP read request from ('192.168.122.119', 50008)
2017-06-06 23:54:26,643 [1213] (INFO) (provd.devices.ident): Processing TFTP request: DISTINCTIVERINGLIST.XML
2017-06-06 23:54:26,643 [1213] (INFO) (provd.devices.ident): <35> Extracted device info: {u'ip': u'192.168.122.119'}
2017-06-06 23:54:26,644 [1213] (INFO) (provd.devices.ident): <35> Retrieved device id: 0c28ba1a9dd24fe188253ea4ad6b54e1
2017-06-06 23:54:26,644 [1213] (INFO) (provd.devices.ident): <35> Routing request to plugin xivo-cisco-sccp-legacy
2017-06-06 23:54:26,644 [1213] (INFO) (provd.servers.tftp.proto): TFTP read request accepted
2017-06-06 23:54:26,644 [1213] (INFO) (twisted): RFC1350Connection starting on 59416
2017-06-06 23:54:26,644 [1213] (INFO) (twisted): Starting protocol <provd.servers.tftp.connection.RFC1350Connection instance at 0x7ff268aa2a28>
2017-06-06 23:54:26,739 [1213] (INFO) (provd.servers.tftp.connection): Datagram received with wrong TID
2017-06-06 23:54:30,571 [1213] (INFO) (provd.servers.tftp.connection): Timeout has expired with current retry count 0
2017-06-06 23:54:30,572 [1213] (INFO) (provd.servers.tftp.connection): Timeout has expired with current retry count 0
2017-06-06 23:54:30,645 [1213] (INFO) (provd.servers.tftp.connection): Timeout has expired with current retry count 0
2017-06-06 23:54:34,571 [1213] (INFO) (provd.servers.tftp.connection): Timeout has expired with current retry count 1
2017-06-06 23:54:34,572 [1213] (INFO) (provd.servers.tftp.connection): Timeout has expired with current retry count 1
2017-06-06 23:54:34,645 [1213] (INFO) (provd.servers.tftp.connection): Timeout has expired with current retry count 1
2017-06-06 23:54:38,572 [1213] (INFO) (provd.servers.tftp.connection): Timeout has expired with current retry count 2
2017-06-06 23:54:38,573 [1213] (INFO) (provd.servers.tftp.connection): Timeout has expired with current retry count 2
2017-06-06 23:54:38,645 [1213] (INFO) (provd.servers.tftp.connection): Timeout has expired with current retry count 2
2017-06-06 23:54:42,573 [1213] (INFO) (provd.servers.tftp.connection): Timeout has expired with current retry count 3
2017-06-06 23:54:42,573 [1213] (INFO) (provd.servers.tftp.connection): Timeout has expired with current retry count 3
2017-06-06 23:54:42,573 [1213] (INFO) (twisted): (UDP Port 37021 Closed)
2017-06-06 23:54:42,573 [1213] (INFO) (twisted): Stopping protocol <provd.servers.tftp.connection.RFC1350Connection instance at 0x7ff268b0efc8>
2017-06-06 23:54:42,573 [1213] (INFO) (twisted): (UDP Port 47638 Closed)
2017-06-06 23:54:42,574 [1213] (INFO) (twisted): Stopping protocol <provd.servers.tftp.connection.RFC1350Connection instance at 0x7ff268aafa70>
2017-06-06 23:54:42,645 [1213] (INFO) (provd.servers.tftp.connection): Timeout has expired with current retry count 3
2017-06-06 23:54:42,646 [1213] (INFO) (twisted): (UDP Port 59416 Closed)
2017-06-06 23:54:42,646 [1213] (INFO) (twisted): Stopping protocol <provd.servers.tftp.connection.RFC1350Connection instance at 0x7ff268aa2a28>

Thanks in advance!

(1-6/6)