<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01 Transitional//EN">
<html>
<head>
  <meta content="text/html; charset=ISO-8859-1"
 http-equiv="Content-Type">
</head>
<body bgcolor="#ffffff" text="#000000">
<br>
Hi,<br>
<br>
See inline.<br>
<br>
On 08/05/2011 03:54 AM, D. Hugh Redelmeier wrote:
<blockquote
 cite="mid:alpine.LRH.2.02.1108041337340.22821@redclaw.mimosa.com"
 type="cite">
  <pre wrap="">| From: Antony Richards <a class="moz-txt-link-rfc2396E" href="mailto:arichards@cybertec.com.au">&lt;arichards@cybertec.com.au&gt;</a>

| On 08/04/2011 04:37 PM, D. Hugh Redelmeier wrote:
| &gt; | From: Antony Richards<a class="moz-txt-link-rfc2396E" href="mailto:arichards@cybertec.com.au">&lt;arichards@cybertec.com.au&gt;</a>
| &gt;
| &gt; | I came across a bug in Openswan.  The box starts up.  Openswan connects.
| &gt; | The
| &gt; | date is set back to 1970, NTPD is started and sets the date to be 2011.
| &gt;
| &gt; That sounds like a bug in ntpd.  How does the date get set to 1970?
| &gt;
| &gt;    
| I explicitly turned off ntpd and set the date back to 1970.  The reason was
| that it quickly reproduced an issue I observed when an Linux embedded device
| I'm developing is first powered on with a pre-loaded configuration.

What were you observing in your embedded system?  Did pluto log the
message about time moving backwards?  Is your system behaving
reasonably?  Does it time-travel at great rates?

  </pre>
</blockquote>
Unfortunately the log files I got from the field did not include the
Openswan logs.&nbsp; All I knew was that new boxes, with the real time
clock's capacitor probably flat, resulted in the command <b>ipsec auto
--status</b> blocking.&nbsp; My discussions internally lead me to the
conclusion that the date must have been changed after Openswan was
started.<br>
<br>
The procedure above (changing the year from 2011 to 1970 then back
2011) caused the observed issue in the field to happen in my testbed.<br>
<br>
<br>
<blockquote
 cite="mid:alpine.LRH.2.02.1108041337340.22821@redclaw.mimosa.com"
 type="cite">
  <pre wrap="">| That would solve the problem also, but using uptime gives a simpler solution.

Yes.

What I don't remember is whether we use results of now() in logging,
implicitly assuming that the values are meaningful to the reader (i.e.
now they are the best-guess at wall-clock time, but with another clock
that might not be the case).

  </pre>
</blockquote>
I don't know the code base well enough to be able to comment on this.&nbsp;
A quick look at gtags-cscope shows that the function time() is called
when clock time is needed.<br>
<blockquote
 cite="mid:alpine.LRH.2.02.1108041337340.22821@redclaw.mimosa.com"
 type="cite">
  <pre wrap="">If you switch to a monotonic clock, the monotonicity-creating feature
of now() ought to be replaced by a monotonicity-checking feature.

| What would the minimum jump in time be before adjusting delta?

If the time jumps past all pending event, logically it could be
clamped at the time of the last event, I would think.  I think that
there is almost always a pending event.  If there is not, then perhaps
the "delta" could be zeroed anyway: nothing is affected by delta in
that case.
  </pre>
</blockquote>
That would work, except the jump would also cause all the events to
prematurely trigger.<br>
<blockquote
 cite="mid:alpine.LRH.2.02.1108041337340.22821@redclaw.mimosa.com"
 type="cite">
  <pre wrap="">
| &gt; It would be good for now() to check if n + delta results in an
| &gt; overflow.  What to do then???  passert failure?
| &gt;
| &gt;    
| If all references in timer.c use changes in time then (and the changes are
| small, eg less than 1 year) then the overflow can be safely handled by doing
| unsigned differences.  Casting the result to a signed number will be correct
| for before, now or after.

| eg
| unsigned int now;
| unsigned int scheduled;

| if (((int)(scheduled - now)) &lt; 0)
| {
|   act on the event.
| }

| I believe this works for signed numbers also (I just did a paper exercise to
| prove it to myself).

| So next_event() and handle_timer_event() need to handle time this way.  This
| should be done irrespective of a change to now().

| I can create a new diff with this change in it - be about a day or so (I'll
| ensure it works with timer overflow).

I don't understand.

The "official" type is time_t.  I'd not want to monkey with that
without a good reason.  And int certainly isn't a good choice for a
replacement.  int might be only 16 bits.

If we were willing to play with types, using unsigned long instead of
time_t gives us more headroom (136 years from 1970 instead of 68 years
from 1970).  But that isn't the right fix.
  </pre>
</blockquote>
I was trying to give an example of how it is safe to allow timer
overflow as long as signed differences between timestamps are always
used.&nbsp; Of course the variable for time has to remain time_t.<br>
<br>
Maybe a better example is if you have an event list based on the second
hand on your watch (ie from 0 to 59).&nbsp; All calculations are using
modulo 60 arithmetic.&nbsp; (In this example we can only schedule an event
up to 30 seconds in advance, and observe old events up to 30 seconds in
the past).<br>
<br>
If an event is scheduled at 5 seconds and it is now 55 seconds (ie -5
modulo 60, if we are using signed number), should it be triggered?&nbsp; As
its 10 seconds in the future or 50 seconds in the past means that the
event is not to be triggered yet (remember we only have a 30 second
horizon).<br>
<br>
If time is unsigned then the value of (<i>scheduled &lt; now</i>) is (5
&lt; <i>55</i>) which is true.&nbsp; Hence do trigger the event.&nbsp; <b>Incorrect
behavour.</b><br>
<br>
If time is signed then the value of&nbsp; (<i>scheduled &lt; now</i>) is (<i>5
&lt; -5</i>) which is false. Hence don't trigger the event.&nbsp; Correct
behavour.<br>
<br>
But the value of (<i>(signed)(scheduled - now) &lt; 0</i>) is (<i>signed(5
- 55) &lt; 0</i>) is (<i>signed(-50) &lt; 0</i>) is (<i>10 &lt; 0</i>)
which is false.&nbsp; Hence don't trigger the event.&nbsp; Correct behavour.<br>
<br>
<br>
<b>Another example.</b> That is an event is scheduled at 29 seconds and
it is now 31 seconds (-29).&nbsp; The event should now be triggered.<br>
<br>
If time is unsigned then the value of (<i>scheduled &lt; now</i>) is
(29 &lt; <i>31</i>) which is true.&nbsp; Hence do trigger the event.&nbsp;
Correct behavour.<br>
<br>
If time is signed then the value of&nbsp; (<i>scheduled &lt; now</i>) is (<i>29
&lt; -29</i>) which is false. Hence do not trigger the event.&nbsp; <b>Incorrect
behavour</b>.<br>
<br>
But the value of (<i>(signed)(scheduled - now) &lt; 0</i>) is (<i>signed(29
- 31) &lt; 0</i>) is (<i>signed(-2) &lt; 0</i>) is (<i>-2 &lt; 0</i>)
which is true.&nbsp; Hence do trigger the event.&nbsp; Correct behavour.<br>
<br>
So the two examples above show that an event scheduler can handle
overflow as long as differences (cast to a signed value) are used.&nbsp; <b>But
direct comparisons cannot be used.</b><br>
<br>
To confirm if this issue affected the issue, I modified 2.4 Openswan to
have the original now() code, but it had the change to timer.c below.&nbsp;
I jumped time back and forth many times, and the command <b>ipsec auto
--status</b> no longer blocked.<br>
<br>
So the original infinite loop I observed has been broken.&nbsp; But when
doing big jumps in time, the items on the event loop will be either
delays (if time jumps backwards) or triggered prematurely (time jumps
forwards).&nbsp; To solve this issue a monotonic increasing clock is needed.<br>
<br>
I've appended a new diff to use clock_systime() and use differences
when comparing times.<br>
<br>
Regards,<br>
Antony.<br>
<br>
<br>
<br>
&nbsp; <br>
<blockquote
 cite="mid:alpine.LRH.2.02.1108041337340.22821@redclaw.mimosa.com"
 type="cite">
  <pre wrap="">
| I'll send a new diff file soon covering these comments (ie changing the maths
| in timer.c and using sys_clock_gettime()).

I'm not yet 100% sold on this whole approach.
_______________________________________________
Dev mailing list
<a class="moz-txt-link-abbreviated" href="mailto:Dev@openswan.org">Dev@openswan.org</a>
<a class="moz-txt-link-freetext" href="http://lists.openswan.org/mailman/listinfo/dev">http://lists.openswan.org/mailman/listinfo/dev</a>
  </pre>
</blockquote>
<br>
<b>New diff file.</b><br>
<br>
Can you check the Makefile changes, I needed to add -lrt when linking,
but not sure if I got this part right.<br>
<br>
<br>
<br>
diff --git a/lib/libopenswan/oswtime.c b/lib/libopenswan/oswtime.c<br>
index 6440258..ec0bde5 100644<br>
--- a/lib/libopenswan/oswtime.c<br>
+++ b/lib/libopenswan/oswtime.c<br>
@@ -34,18 +34,13 @@<br>
&nbsp;time_t<br>
&nbsp;now(void)<br>
&nbsp;{<br>
-&nbsp;&nbsp;&nbsp; static time_t delta = 0<br>
-&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; , last_time = 0;<br>
-&nbsp;&nbsp;&nbsp; time_t n = time(NULL);<br>
-<br>
-&nbsp;&nbsp;&nbsp; passert(n != (time_t)-1);<br>
-&nbsp;&nbsp;&nbsp; if (last_time &gt; n)<br>
+&nbsp;&nbsp;&nbsp; struct timespec tp;<br>
+&nbsp;&nbsp;&nbsp; if (clock_gettime(CLOCK_MONOTONIC, &amp;tp) != 0)<br>
&nbsp;&nbsp;&nbsp;&nbsp; {<br>
-&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; openswan_log("time moved backwards %ld seconds",
(long)(last_time - n));<br>
-&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; delta += last_time - n;<br>
+&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; passert(0);<br>
+&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; return 0;<br>
&nbsp;&nbsp;&nbsp;&nbsp; }<br>
-&nbsp;&nbsp;&nbsp; last_time = n;<br>
-&nbsp;&nbsp;&nbsp; return n + delta;<br>
+&nbsp;&nbsp;&nbsp; return (time_t)tp.tv_sec;<br>
&nbsp;}<br>
&nbsp;<br>
&nbsp;/* Names of the months */<br>
diff --git a/programs/Makefile.program b/programs/Makefile.program<br>
index 800e0db..06fd400 100644<br>
--- a/programs/Makefile.program<br>
+++ b/programs/Makefile.program<br>
@@ -37,6 +37,7 @@ endif<br>
&nbsp;CFLAGS+= ${NAT_DEFS}<br>
&nbsp;<br>
&nbsp;LIBS?=${PROGLIBS} ${OSWLOGLIB} ${OPENSWANLIB} ${CRYPTOLIBS} <br>
+LIBS+= -lrt<br>
&nbsp;<br>
&nbsp;ifeq ($(USE_NAT_TRAVERSAL),true)<br>
&nbsp;CFLAGS+= -DNAT_TRAVERSAL<br>
diff --git a/programs/pluto/Makefile.options
b/programs/pluto/Makefile.options<br>
index 99f0196..7c24f92 100644<br>
--- a/programs/pluto/Makefile.options<br>
+++ b/programs/pluto/Makefile.options<br>
@@ -343,3 +343,5 @@ endif<br>
&nbsp;ifeq ($(USE_NM),true)<br>
&nbsp;DEFINES+=-DHAVE_NM<br>
&nbsp;endif<br>
+<br>
+LIBSPLUTO+= -lrt<br>
diff --git a/programs/pluto/timer.c b/programs/pluto/timer.c<br>
index 516aef3..2fa4ee5 100644<br>
--- a/programs/pluto/timer.c<br>
+++ b/programs/pluto/timer.c<br>
@@ -400,7 +400,7 @@ handle_timer_event(void)<br>
&nbsp;&nbsp;&nbsp;&nbsp; type = ev-&gt;ev_type;<br>
&nbsp;&nbsp;&nbsp;&nbsp; tm = now();<br>
&nbsp;<br>
-&nbsp;&nbsp;&nbsp; if (tm &lt; ev-&gt;ev_time)<br>
+&nbsp;&nbsp;&nbsp; if (tm - ev-&gt;ev_time &lt; 0)<br>
&nbsp;&nbsp;&nbsp;&nbsp; {<br>
&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; DBG(DBG_CONTROL, DBG_log("called while no event expired
(%lu/%lu, %s)"<br>
&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; , (unsigned long)tm, (unsigned long)ev-&gt;ev_time<br>
@@ -418,7 +418,7 @@ handle_timer_event(void)<br>
&nbsp;&nbsp;&nbsp;&nbsp; /*<br>
&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; * we can get behind, try and catch up all expired events<br>
&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; */<br>
-&nbsp;&nbsp;&nbsp; while (ev &amp;&amp; tm &gt;= ev-&gt;ev_time) {<br>
+&nbsp;&nbsp;&nbsp; while (ev &amp;&amp; (tm - ev-&gt;ev_time &gt;= 0)) {<br>
&nbsp;<br>
&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; handle_next_timer_event();<br>
&nbsp;<br>
<br>
<br>
</body>
</html>