Some Eclipse Foundation services are deprecated, or will be soon. Please ensure you've read this important communication.

Bug 351305

Summary:	"Invalid Datagram Packet Received" error logged when system clock not accurate
Product:	[Tools] TCF	Reporter:	Martin Oberhuber <mober.at+eclipse>
Component:	Core	Assignee:	Project Inbox <tcf.core-inbox>
Status:	RESOLVED FIXED	QA Contact:	Eugene Tarassov <eugene>
Severity:	normal
Priority:	P3	CC:	cdtdoug
Version:	unspecified
Target Milestone:	0.4.0
Hardware:	PC
OS:	Linux-GTK
Whiteboard:

Description Martin Oberhuber

2011-07-06 07:12:06 EDT

Build ID: CDT 8.0 (Indigo)

I happened to run Eclipse on a machine where the system clock was lagging (by little more than 1 hour). As a result, I got several errors logged like this:

java.lang.Exception: Invalid slave info timestamp: 1309949737136 -> 2011-07-06 12:55:37.136

I see how a slave info timestamp in the future looks incorrect, but the way how this is logged doesn't help me understand or diagnose the problem. Questions:

- What can really go wrong when TCF instances on a local network are not
  synced in time? Note that some end users may not have permission to change
  the system clock, and for some deployed/managed devices it may not even 
  be possible to easily change/adjust the system clock.

- Is there a way TCF could work properly without clocks synced?

- If not, could the error logging be improved? Eg "slave info timestamp seems
  to be in the future, please check your system clock".

For completeness, here's the stacktrace from the error in my log:


	at org.eclipse.tm.internal.tcf.services.local.LocatorService.handleSlavesInfoPacket(LocatorService.java:1098)
	at org.eclipse.tm.internal.tcf.services.local.LocatorService.handleDatagramPacket(LocatorService.java:985)
	at org.eclipse.tm.internal.tcf.services.local.LocatorService.access$7(LocatorService.java:956)
	at org.eclipse.tm.internal.tcf.services.local.LocatorService$3$1.run(LocatorService.java:287)
	at org.eclipse.tm.tcf.protocol.Protocol$3.run(Protocol.java:209)
	at org.eclipse.tm.tcf.EventQueue.run(EventQueue.java:99)
	at java.lang.Thread.run(Thread.java:619)

Comment 1 Eugene Tarassov

2011-07-06 11:30:46 EDT

This looks like duplicate of Bug 333610, which is supposed to be fixed.

Comment 2 Martin Oberhuber

2011-07-06 11:40:12 EDT

I double-checked I was using o.e.tm.tcf.core 0.4.0.201106081058 ... the message was logged once per session per peer only, but it was logged.

Comment 3 Martin Oberhuber

2011-07-06 11:49:31 EDT

... though interestingly, I cannot reproduce this now with a system where I deliberately changed the clock.

Comment 4 Eugene Tarassov

2011-07-06 11:53:44 EDT

The messages can be caused by an old agent running somewhere on your local network.

Comment 5 Martin Oberhuber

2011-07-06 12:08:41 EDT

Hm... how could I diagnose that?

For the log entry below, I'm 100% sure that the local tcf is current, and I'm 95% sure that the remote agent was current. As you see, this log entry is kind of "the other end" of the original log entry (comment #0 was from 193.81.18.166)... though I must confess it's confusing that the line number information in this log entry is different, so perhaps the remote agent was in fact old.

!ENTRY org.eclipse.tm.tcf 4 0 2011-07-06 13:01:02.154
!MESSAGE Invalid datagram packet received from /193.81.18.166/1534
!STACK 0
java.lang.Exception: Invalid slave info timestamp: 1309946265446 -> 2011-07-06 11:57:45.446
	at org.eclipse.tm.internal.tcf.services.local.LocatorService.handleSlavesInfoPacket(LocatorService.java:1075)
	at org.eclipse.tm.internal.tcf.services.local.LocatorService.handleDatagramPacket(LocatorService.java:954)
	at org.eclipse.tm.internal.tcf.services.local.LocatorService.access$7(LocatorService.java:929)
	at org.eclipse.tm.internal.tcf.services.local.LocatorService$3$1.run(LocatorService.java:287)
	at org.eclipse.tm.tcf.protocol.Protocol$3.run(Protocol.java:209)
	at org.eclipse.tm.tcf.EventQueue.run(EventQueue.java:99)
	at java.lang.Thread.run(Unknown Source)

Comment 6 Eugene Tarassov

2011-07-06 12:47:41 EDT

I think I know what is causing the problem. I have found one place in Java version of Locator service code that correctly computes time-to-live, but then still erroneously sends absolute time stamp instead of just computed value. I will commit a fix.

Comment 7 Eugene Tarassov

2011-07-06 13:02:52 EDT

Committed a fix into both trunk and 0.4.0 release branch.