NMC2 (AP9631) "File Transfer Failed" notification (confusing)

[josh_apc]

I recently reset my notification settings by adjusting the event groups, and then adjusting settings depending on what notifications I was receiving too often, etc.

The final item that I cannot find is related to an email with this message (after the standard info like ups name, ip address, serial number, etc):

Date : 10/05/2016
Time : 03:01:35
Code : 0x000F

Informational - File transfer failed.

I've been searching google and this forum, but I cannot seem to find what is causing this message. I know it is an informational level message and not an error, and I know that I can turn off the event logging for it, but I wanted to understand why it's happening in the first place.

I searched through settings but couldn't find anything that may be attempting a file transfer. If something was attempting a file transfer to the unit, I'd expect an email about the start of the file transfer (I double-checked and those emails are indeed enabled). I receive no other emails about file transfers, however.

This is from an AP9631 in an SMX1500RM2UNC with a single SMX48RMBP2U attached.

AOS 6.4.0 (boot monitor 1.0.8) and UPS Firmware 03.8 (ID11)

Any help/information would be great.

Thank you.

-Josh

[BillP]

Hi Josh,

I will research what triggers this event. In the meantime, could you provide us the event.txt file (you can export the full log file through the web UI by clicking the disk icon when viewing the log) so we can see the event in context?

Thanks!

[BillP]

Hi Josh,

I had someone look for me and they said this message occurs when a FTP, TFTP, or SCP file transfer fails. It can also occur if a firmware file load (.bin file) fails a header check as well.

If I can see your full log, I can shed some more light on this if none of this sounds right.

[josh_apc]

Thanks for the quick responses.

So, I have not initiated any file transfers, of any kind. This message appears daily (sometimes the only message during a day). I thought maybe something was attempting to send a file, but then it confused me because I receive no notification of the file transfer starting. If nothing is starting (at least no notification of such), how can anything fail?

I've attached the event log, with the serial number scrubbed. I'm not sure that makes any difference, but just mentioning that I made that change.

[BillP]

Hi Josh,

Thanks for the event log - don't need the serial number but thanks for the FYI. The one thing that comes to mind was if a DHCP server was attempting to use the DHCP RFC boot file option explained in http://www.apc.com/us/en/faqs/FA156110 and it is not configured properly. Sure enough, I checked your log and you are using a DHCP address and your lease is 24 hours long. Could you check to see if this is a possibility and that your DHCP server supports this option/options (I think this spans multiple options like 66, 67)?

See in the log it happened right after the NMC rebooted and got a lease also?

2016-09-05	19:55:59	System	File transfer failed.	0x000F
2016-09-05	19:55:52	apc	Web user 'apc' logged in from 192.168.2.4.	0x0015
2016-09-05	19:55:47	System	Network service started. System IP is 192.168.2.253 from DHCP server 192.168.2.1 with 86389 second lease.	0x0007
2016-09-05	19:55:46	Device	UPS: Restored the local network management interface-to-UPS communication.	0x0101
2016-09-05	19:55:30	System	Network service started. IPv6 address FE80::2C0:B7FF:FEC3:E7C1 assigned by link-local autoconfiguration.	0x0007
2016-09-05	19:55:24	System	Network Interface restarted.	0x0002

I'd have to check your config.ini file if the file transfer started events are truly enabled everywhere. I'd expect to see them in the log at least even if you disabled them from email notifications. You can also double check under Configuration->Notification->Event Actions->By event, go to System heading and click on that and search for the file transfer started events and make sure that you see a bullet in the event log column indicating they are enabled for logging in the event log.

[josh_apc]

Very clever catch.  I checked my DHCP  server and it is set to 7 day lease  (604800 seconds) on DHCP  requests which do NOT  request a specific lease time. 

The default maximum is 86400 for those which DO  request a specific release time.

I do have TFTP  enabled (option 66, along with the boot file, 67), so that may be the issue. It's unfortunate that the error message is so vague.

I'm curious why it isn't reporting DHCP  information for each file transfer failed message, but perhaps it doesn't report unless it changes, or on startup.

Here are my settings from the config.ini, related to file transfer notifications:

; FTP File transfer started.
E000C=E,E[+:::],T[:::::],P[:::]

; TFTP File transfer started.
E000D=E,E[+:::],T[:::::],P[:::]

; File transfer failed.
E000F=E,E[+:::],T[:::::],P[:::]

So, again, if it's the TFTP setting in the DHCP server, it seems odd that I wouldn't also see event messages for the TFTP file transfer started (since the settings appear the same as the file transfer failed setting).

I have attempted some further testing, but have not yet been successful. So far, I've tried to reboot the NMC, but there was no failed file transfer event. I've checked my DHCP server (which is a pfSense machine, btw) and nothing seems obvious other than having TFTP enabled. The NMC has a static DHCP assignment, so that may affect the response (not sending one for the NMC reboot, since it hasn't expired, etc).

I've also attempted to use dhcpdump/dhcping to review the options in the dhcp response. It does show the FNAME field (option 67) is populated, so I'm guessing that's the issue. It also shows the lease time as 86400, which does match a full day, but doesn't match the 86389 that shows in the event logs of the NMC. Perhaps an unrelated bug?

I'm going to disable TFTP for now, and see if the issue goes away. I haven't used that for a while anyway.

I would request that the error message be enhanced, or perhaps review the TFTP file transfer event logging, since I would expected to have gotten that message as well.

Thanks again for the help. Unless I can find a way to properly trigger the failure from the NMC, I'll just have to wait for a bit and see if the issue stops. I'll report back in a day or two, or once I know more.

-Josh

[BillP]

Hi Josh,

Thanks for your feedback. Your config shows those events are enabled for logging. In looking at a quick example:

; File transfer failed.
E000F=E,E[+:::],T[:::::],P[:::]

The E000F is the event code which we show as 0x000F in the UI. After the =, the first E indicates enabled for event log - so that question is answered. The subsequent E, T, and P with bracket sections refer to email, trap, and paging configurations which some or all may be supported on your device (like paging wouldn't be) but it still shows. The email config has 3 colons to separate configuration for up to 4 email recipients. Reading this is very cryptic but we have a document on it, though don't recommend people necessarily read it from here. What I can eyeball is basically as much as I've told you. The only other thing is the plus sign means it is enabled for messages, a - character would mean it is specifically disabled. I think that is maybe all you can have there for this type of informational event rather than other events which you can set up repeats/delays for that continue along and require a condition to clear it such as UPS on battery/no longer on battery.

Anyway, in reading what you've looked at and researched so far, yes, hopefully the messages stop. I imagine that the "File transfer failed" is vague so that it can be used for multiple situations.

If you confirm that whatever you did stops the file transfer failed messages, then I'd like to use your scenario and setup as an example to file a request to potentially enhance the logging - don't know if it is possible with how this event is triggered, used, etc, though I hope so. I just want to explain how you have a DHCP server, what was configured on it, etc so that someone could replicate it possibly if they needed to and can understand why things are acting the way that they are to make changes. That will help development make sure that any changes actually fix your issue, assuming this is all okay with you.

On the lease seconds, I'd probably see if you can catch the value of 86400 in a packet capture somewhere coming from your server so then I can log a bug on that if I need to showing that the DHCP server is sending 86400 but the NMC is logging something differently - 80389.

[josh_apc]

Thanks for the confirmation. I had guessed the structure of the config file, but appreciate the confirmation. My main point was that the TFTP file transfer started and the file transfer failed settings are the same. Yet I never receive a TFTP file transfer started email ( I do, obviosuly, receive the failure message, since that's what started this discussion in the first place). This was the portion I was referencing 

As for the config information, I'll definitely work with you and get details to you once I can prove/disprove that the TFTP portion was the issue. If nothing else, I think that if I had received the "TFTP transfer started" notification (or if it were at least added to the event log), I would have known where to look. Perhaps a more detailed "failure" message would be good, but I do understand having the generic option allows for it to be used for multiple scenarios. I can appreciate that aspect, but it fails when you don't know what started and then failed.

For the "seconds" difference, I do have a dhcpdump output, if that helps. I've attached the file for reference.

You can see that the DHCPACK response contains the leasetime of 86400. If that is not the proper way that someone needs to see the info, please let me know.

Thanks, again, you've been most helpful so far.

-Josh

[BillP]

Thanks Josh. Totally agree with you from a user perspective the logging could use an adjustment.

On the lease time thing, thank you. I think that would be adequate. But, I just found this note actually when I was verifying this wasn't already known/documented: The TCP/IP stack assumes the DHCP server begins counting down the lease time when the discover message is sent out. Therefore, it subtracts the amount of time that passed between getting the initial offer and the final accept, which is usually about 10 seconds.

So, I think that is our answer as to the difference?

[josh_apc]

Yes, that does appear to account for the difference.

From my point of view, I'd rather know the response sent, since the network status doesn't show me the seconds anyway. The event log does show the hour, minute, second value, but it was only off by ~1 second, which could just be the time to acknowledge the response and write the event to the log file, plus any slight time difference in the systems.

Anyway, I'd say you are accurate that it is a known difference, and there was a choice to report it that way. With that said, it seems like it would be more useful to know the response from the server, not an estimate of how much is left at that time. Also, it would be nice to have control over the lease request coming from the NMC. As it is, if I don't want the NMC asking for an IP every single day, I have to assign a static IP to it. I'd rather a DHCP setup, where I assign the static IP within my router, for ease of control and flexibility. That would mean either not specifying a lease time in the request, or allowing a configuration setting for that value (blank to take whatever the dhcp server provides, or specify a value to override the dhcp server, etc).

So that leaves this to a request for another configuration option for the DHCP setup, a possible event log change, and then a waiting game to see whether or not the file transfer issue is resolved (at which time the TFTP transfer start notification should get investigated because it would mean that it wasn't triggering).

If I've missed anything, let me know. Otherwise I'll report back in a day or two, as stated.

-Josh

[BillP]

Hi Josh,

Yes, I think you have it right. Do you have an example of a DHCP client that offers what you're asking already? I can't say I've seen this on any of the devices I use that support DHCP - whether home or work stuff. I can't think of anything in general off the top of my head that offers flexibility pertaining to what you suggested but if I have an example, it makes the request and justification easier. And, anything we'd do we would want to follow the RFC.I might not have noticed a good example with what I use since I am often using static addresses.

What we offer or have offered that I'd seen is those DHCP options I showed you such as option 43 configuration, ability to configure retries (in certain firmwares), and ability to allow static NTP and DNS servers to be overwritten (or not) by DHCP options for those items.

Thanks! Talk to you soon.

[josh_apc]

I don't have a great example for DHCP options including the requested lease time. I was simply guessing at an idea to get around some of these issues.

However, something bugged me about this: reviewing the dhcpdump info, I see the router responding with option 51 (lease time), but I never see it actually requested. Based on the settings in the dhcp server, I was assuming it assigning the 86400 because the request was being made (based on wording, etc). However, based on that, I did some testing to see if I could prove what value was being requested...

In doing so, I must sincerely apologize. I believe I was wrong and the NMC is working how I would want (not requesting a lease expiration time). I may have actually found a corner-case style bug in the router software. It's a boring story, so I won't bother sharing it here, but basically it's been assigning all leases at a day (which actually explains another system which was next on my list to review for dhcp "oddness").

So, at least one aspect is cleared up. I still think it would be nicer to have the event report the value actually reported by the dhcp server (86400 vs 86389, in my case). Again, I apologize for drawing this out and not testing that aspect sooner. Changing some of those values seemed like a poor work-around and I avoided that test. However, in this case it proved to highlight that the issue was not in the NMC. Small win!

I will still be certain to check back and report on whether the TFTP truly is the cause of the original issue.

So, now we're down to just a request to change the event log wording.

Wow. Maybe, in the future, I won't be so long-winded. Thank you, again, for all of your help.

This is, by far, some of the best customer service I've had from a product forum.

-Josh

[BillP]

Hi Josh,

Thanks for explaining. Glad to help  I think you're slightly lucky since my expertise for the last ~10 years is this product - Network Management Cards (among some others) - and I work closely with the development teams (for the different application firmwares NMC2 goes into) so I have a lot of resources at my disposal to answer these types of questions and support these types of issues.

I will await your confirmation on the TFTP thing. Assuming that fixes it, then I will try to come with a summary for the enhancement request so we can have someone check into seeing if we can make the logging for this better.

Talk to you soon!

[josh_apc]

I apologize for the delayed response. In my testing, I noticed that the DHCP lease on the NMC had been bumped to 3.5 days, so I wanted to ensure that the standard process (not just me resetting the card) passed the test.

I have not received any further file transfer errors since my last update. A new lease was acquired last night, and no errors were reported. The lease is now good for 7 days, so the issue in my router is also cleared up (I did report the odd corner-case style bug, but at least I know to have both values set now).

So, the biggest thing I'd request would be to look into why I was never getting any indication that the TFTP transfer had started. I'd guess because it could never find the file in the first place and so no actual transfer started. However, I'd assume that the start of the process would trigger the email, then if the process failed, I'd get the failure notification. If it's triggered by an actual beginning of a file downloading, that seems too late since I only received the failure notice. Again, to clarify, the biggest issue with only receiving the failure is that I was not aware what was failing.

Thanks again for all of the help. As stated before, I'm definitely willing to help by providing more information or testing.

[BillP]

Hi Josh,

Thanks for the update. I'll be on vacation for about a week now so I'll have to work on this when I return middle of next week. I anticipate having to discuss the current behavior with development and seeing where and if changes can being made which would then likely need to an enhancement request or a bug depending on the current behavior's design.

I'll touch base with you by end of next week either way with some sort of update when I return.

[BillP]

Hi Josh,

Sorry about the delay. Still have this on my to-do list. Haven't been able to find good time where both me and development have been available to discuss this in depth. I'll be traveling next week again but rest assured that I haven't forgotten about seeing what we can do about this for a future firmware release.

[BillP]

Hi Josh - just wanted to follow up. Could you confirm that the file transfer failed messages still aren't coming back? In the meantime, I am working on trying to answer your question and am currently assuming you are no longer receiving the message after making the adjustment on your router.

[josh_apc]

Confirmed, I have not been receiving the failed transfer message since I disabled TFTP ability in my router. So it was definitely attempting to download the offered file (via TFTP), but not reporting that it had started a TFTP transfer, then failing to find the file, and finally reporting that the transfer had failed.

[BillP · Accepted solution]

Thanks for confirming. I am logging an bug/enhancement request right now based on your feedback to get this prioritized by the development team.