TFTP timeout troubleshooting

[stevech]

MVP screwing up again during boot. This time I put on the analytical hat instead of just waiting for the right phase of the moon.

Analyzing the debugging log, after power-up of the MVP,
I see that Sage's server saw client on the correct IP address.
TFTP began.
Sun 7/15 17:31:41.090 Received tftp packet
Sun 7/15 17:31:41.091 Reading dongle.bin.ver in mode octet
Sun 7/15 17:31:41.094 Received tftp packet
Sun 7/15 17:31:41.095 Reading dongle.bin in mode octet
Sun 7/15 17:31:41.095 Opening file
Sun 7/15 17:31:41.144 TFTP timeout
Sun 7/15 17:31:41.145 Retry count exceeded
Sun 7/15 17:31:42.912 At last block
Sun 7/15 17:31:42.972 TFTP timeout
Sun 7/15 17:31:43.035 TFTP timeout
Sun 7/15 17:31:43.097 TFTP timeout
Sun 7/15 17:31:43.160 TFTP timeout
[etc for dozens of TFTP timeouts]
Sun 7/15 17:31:49.222 Retry count exceeded

In the above, these lines are telling:
Sun 7/15 17:31:41.095 Reading dongle.bin in mode octet
Sun 7/15 17:31:41.095 Opening file
Sun 7/15 17:31:41.144 TFTP timeout
Sun 7/15 17:31:41.145 Retry count exceeded

at 17:31:41.095 it commences sending to the MVP.
at 17:31:41.144 it complained of a TFTP timeout. It didn't show in the log that data was sent to the MVP, but we assume it was.
The timeout is about .144 minus .095 = 0.049 seconds. That seems way too short, even at LAN speeds, plus who knows how much time the MVP needs on the first and then the nTh packet. Retry count exceeded - log doesn't reveal retries, maybe they're inside TFTP. Why the short timeout? (No wireless here. Idle LAN. No routing needed, same subnet. Same switch.)

Then, it appears to me that the MVP tries to execute the incomplete downloaded program image and then does unpredictable things. This would be a Hauppauge bug? Or somehow Sage was supposed to tell the MVP the file size that's coming, or at give it an "OK GO" command if successful?

The reason I say the above is that after the "Retry count exceeded", in the log above, the next thing in the log is the following, which may mean that the MVP tried to execute the bad download and the server has ignored that the last thing that happened on the client is a Retry Timeout on TFTP.


Sun 7/15 17:31:53.863 Dropping old MiniPlayer connection because it's old from:000dfe225c62
Sun 7/15 17:31:55.233 Server got broadcast packet: java.net.DatagramPacket@47e53a
Sun 7/15 17:31:55.411 Server sent back mini discovery data:java.net.DatagramPacket@47e53a to /192.168.1.100 3072
Sun 7/15 17:31:55.428 MiniUI got connection from Socket[addr=/192.168.1.100,port=3115,localport=31099]
Sun 7/15 17:31:55.429 MiniUI is adding to its map:000dfe225c62
Sun 7/15 17:31:55.429 Creating new UI for client:000dfe225c62
Sun 7/15 17:31:55.430 Creating-2 new UI for client:000dfe225c62 UIManager:localhost@@000dfe225c62-1b0caf
Sun 7/15 17:31:55.599 MiniUI established for 000dfe225c62
Sun 7/15 17:31:56.214 MiniClient GFX_TEXTMODE=NONE
Sun 7/15 17:31:56.215 MiniClient GFX_BLENDMODE=PREMULTIPLY
Sun 7/15 17:31:56.216 MiniClient GFX_DRAWMODE=UPDATE
Sun 7/15 17:31:56.217 MiniClient GFX_BITMAP_FORMAT=RAW32
Sun 7/15 17:31:56.217 MiniClient GFX_SCALING=null
Sun 7/15 17:31:56.218 MiniClient GFX_OFFLINE_IMAGE_CACHE=null
Sun 7/15 17:31:56.219 MiniClient GFX_SUPPORTED_ASPECTS=4:3,16:9
Sun 7/15 17:31:56.220 MiniClient GFX_ASPECT=4:3
Sun 7/15 17:31:56.221 MiniClient GFX_SUPPORTED_RESOLUTIONS=720x480i@59.94;720x576i@50
Sun 7/15 17:31:56.221 MiniClient GFX_RESOLUTION=
Sun 7/15 17:31:56.222 MiniClient GFX_COMPOSITE=BLEND
Sun 7/15 17:31:56.223 MiniClient GFX_COLORKEY=00000000
Sun 7/15 17:31:56.224 MiniClient INPUT_DEVICES=null
Sun 7/15 17:31:56.225 MiniClient DISPLAY_OVERSCAN=null
Sun 7/15 17:31:56.226 MiniClient VIDEO_CODECS=MPEG2-VIDEO
Sun 7/15 17:31:56.226 MiniClient AUDIO_CODECS=MPG1L2,MPG1L3,AC3
Sun 7/15 17:31:56.227 MiniClient PULL_AV_CONTAINERS=null
Sun 7/15 17:31:56.228 MiniClient PUSH_AV_CONTAINERS=MPEG2-PS
Sun 7/15 17:31:56.229 MiniClient FIXED_PUSH_MEDIA_FORMAT=null
Sun 7/15 17:31:56.229 MiniClient DETAILED_BUFFER_STATS=null
Sun 7/15 17:31:56.230 MiniClient PUSH_BUFFER_SEEKING=null
Sun 7/15 17:31:56.231 MiniClient MEDIA_PLAYER_BUFFER_DELAY=null
Sun 7/15 17:31:56.232 MiniClient IR_PROTOCOL=RC5
Sun 7/15 17:31:56.233 MiniClient CRYPTO_ALGORITHMS=null
Sun 7/15 17:31:56.233 Creating-3 new UI for client:000dfe225c62 UIManager:localhost@@000dfe225c62-1b0caf
Sun 7/15 17:31:56.235 UIMgr loading UI from: C:\Program Files\SageTV\SageTV\STVs\SageTV3\SageTV3.xml
Sun 7/15 17:31:56.238 VF thread is now running...
Sun 7/15 17:31:56.239 VF thread is now waiting for 0:00:00.000
Sun 7/15 17:31:56.993 UIMgr done loading UI from: C:\Program Files\SageTV\SageTV\STVs\SageTV3\SageTV3.xml
Sun 7/15 17:31:56.998 Hidden Extras are DISABLED
Sun 7/15 17:31:57.010 setUI(sage.b2@d733ca[Main Menu]) histIdx=0 uiHistory=[sage.b2@d733ca[Main Menu]]
Sun 7/15 17:31:57.025 Creating-4 new UI for client:000dfe225c62 UIManager:localhost@@000dfe225c62-1b0caf
Sun 7/15 17:31:57.026 MiniUI got connection from Socket[addr=/192.168.1.100,port=3116,localport=31099]
Sun 7/15 17:31:57.027 MiniPlayer is adding to its map:000dfe225c62

[at this point- MVP display is "Sage TV Media Center Is Starting Up..."
forever. In prior screwups, the incomplete images have yielded different behavior, such as MVP looping with flashing screens, and other odd things that can happen based on what was left over in the uninitialized RAM for executable code).

I hope this helps someone troubleshoot this recurring problem. Why it works well so often then not is a mystery.

I'll keep experimenting.

[carlgar]

I think seeing a wireshark capture would be the easiest way of see what is going wrong.
Is this a wired MVP or a Wireless MVP?
Do you have a router in your network?
Do you have multiple NIC's on your server system?

[stevech]

Originally Posted by carlgar

I think seeing a wireshark capture would be the easiest way of see what is going wrong.
Is this a wired MVP or a Wireless MVP?
Do you have a router in your network?
Do you have multiple NIC's on your server system?

I addressed each of these in the posting...
wired.
Router yes, but MVP and server are on the same L2 switch.
multiple NICs in server: no.

[carlgar]

I just looked at a capture from a friend and it looks like it should take 7 to 10 seconds to properly load the software into the MVP. The download is done using UDP protocol which does not have much error checking. I would have to presume that you did lose a lot of packets and probably are executing garbage. I think you probably should just power off and back on until you get a good load. Once you have a good load you should only use the remote to power on and on, so you don't have to reload (except for a new sage release) the software.

[stevech]

Thanks. I have powered off/on dozens of times.
I unplugged (RJ45) all IP devices except the MVP and server from the LAN ports.
Rebooted all LAN devices and servers many times. Etc etc.

I am running some grabs with WireShark - studied quite a few. Can't understand what is going on, other than DHCP to the router works, and the MVP ARPs for .208, the server's address that the MVP has discovered. I did see one instance of *three* UDP packets to the MVP. But no more. That may match what I saw in the Sage logfile. As we all know, UDP error correction is the responsibility of the session layer, unlike TCP. I believe that TFTP uses UDP not TCP.

The short amount of time for the TFTP timeout, in the beginning of this thread, is the only real clue.

[stevech]

MVP display changed from repeated
... Starting Up
to
[loading, loading, then]
Failed To Locate GUI server

so now, the log says
un 7/15 21:02:31.530 Sending mvp reply
Sun 7/15 21:02:31.537 Received tftp packet
Sun 7/15 21:02:31.538 Reading dongle.bin.ver in mode octet
Sun 7/15 21:02:31.544 Received tftp packet
Sun 7/15 21:02:31.546 Reading dongle.bin in mode octet
Sun 7/15 21:02:31.546 Opening file
Sun 7/15 21:02:31.591 TFTP timeout
Sun 7/15 21:02:31.591 Retry count exceeded
Sun 7/15 21:02:32.059 TFTP error 4
Sun 7/15 21:02:32.060 TFTP error 4
Sun 7/15 21:02:32.062 Received tftp packet
Sun 7/15 21:02:32.064 Reading dongle.bin in mode octet
Sun 7/15 21:02:32.064 Opening file
Sun 7/15 21:02:32.111 TFTP timeout
Sun 7/15 21:02:32.162 TFTP timeout