programs/pluto/timer.c

   1 /* timer event handling
   2  * Copyright (C) 1997 Angelos D. Keromytis.
   3  * Copyright (C) 1998-2001  D. Hugh Redelmeier.
   4  *
   5  * This program is free software; you can redistribute it and/or modify it
   6  * under the terms of the GNU General Public License as published by the
   7  * Free Software Foundation; either version 2 of the License, or (at your
   8  * option) any later version.  See <http://www.fsf.org/copyleft/gpl.txt>.
   9  *
  10  * This program is distributed in the hope that it will be useful, but
  11  * WITHOUT ANY WARRANTY; without even the implied warranty of MERCHANTABILITY
  12  * or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
  13  * for more details.
  14  *
  15  * RCSID $Id: timer.c,v 1.5 2004/09/17 21:36:57 as Exp $
  16  */
  17
  18 #include <stdio.h>
  19 #include <stdlib.h>
  20 #include <sys/types.h>
  21 #include <time.h>
  22 #include <unistd.h>
  23 #include <netinet/in.h>
  24 #include <arpa/inet.h>
  25 #include <sys/queue.h>
  26
  27 #include <freeswan.h>
  28
  29 #include "constants.h"
  30 #include "defs.h"
  31 #include "connections.h"
  32 #include "state.h"
  33 #include "demux.h"
  34 #include "ipsec_doi.h"  /* needs demux.h and state.h */
  35 #include "kernel.h"
  36 #include "server.h"
  37 #include "log.h"
  38 #include "rnd.h"
  39 #include "timer.h"
  40 #include "whack.h"
  41
  42 #ifdef NAT_TRAVERSAL
  43 #include "nat_traversal.h"
  44 #endif
  45
  46 /* monotonic version of time(3) */
  47 time_t
  48 now(void)
  49 {
  50     static time_t delta = 0
  51         , last_time = 0;
  52     time_t n = time((time_t)NULL);
  53
  54     passert(n != (time_t)-1);
  55     if (last_time > n)
  56     {
  57         plog("time moved backwards %ld seconds", (long)(last_time - n));
  58         delta += last_time - n;
  59     }
  60     last_time = n;
  61     return n + delta;
  62 }
  63
  64 /* This file has the event handling routines. Events are
  65  * kept as a linked list of event structures. These structures
  66  * have information like event type, expiration time and a pointer
  67  * to event specific data (for example, to a state structure).
  68  */
  69
  70 static struct event *evlist = (struct event *) NULL;
  71
  72 /*
  73  * This routine places an event in the event list.
  74  */
  75 void
  76 event_schedule(enum event_type type, time_t tm, struct state *st)
  77 {
  78     struct event *ev = alloc_thing(struct event, "struct event in event_schedule()");
  79
  80     ev->ev_type = type;
  81     ev->ev_time = tm + now();
  82     ev->ev_state = st;
  83
  84     /* If the event is associated with a state, put a backpointer to the
  85      * event in the state object, so we can find and delete the event
  86      * if we need to (for example, if we receive a reply).
  87      */
  88     if (st != NULL)
  89     {
  90         if (type == EVENT_DPD || type == EVENT_DPD_TIMEOUT)
  91         {
  92             passert(st->st_dpd_event == NULL);
  93             st->st_dpd_event = ev;
  94         }
  95         else
  96         {
  97             passert(st->st_event == NULL);
  98             st->st_event = ev;
  99         }
 100     }
 101
 102     DBG(DBG_CONTROL,
 103         if (st == NULL)
 104             DBG_log("inserting event %s, timeout in %lu seconds"
 105                 , enum_show(&timer_event_names, type), (unsigned long)tm);
 106         else
 107             DBG_log("inserting event %s, timeout in %lu seconds for #%lu"
 108                 , enum_show(&timer_event_names, type), (unsigned long)tm
 109                 , ev->ev_state->st_serialno));
 110
 111     if (evlist == (struct event *) NULL
 112     || evlist->ev_time >= ev->ev_time)
 113     {
 114         ev->ev_next = evlist;
 115         evlist = ev;
 116     }
 117     else
 118     {
 119         struct event *evt;
 120
 121         for (evt = evlist; evt->ev_next != NULL; evt = evt->ev_next)
 122             if (evt->ev_next->ev_time >= ev->ev_time)
 123                 break;
 124
 125 #ifdef NEVER    /* this seems to be overkill */
 126         DBG(DBG_CONTROL,
 127             if (evt->ev_state == NULL)
 128                 DBG_log("event added after event %s"
 129                     , enum_show(&timer_event_names, evt->ev_type));
 130             else
 131                 DBG_log("event added after event %s for #%lu"
 132                     , enum_show(&timer_event_names, evt->ev_type)
 133                     , evt->ev_state->st_serialno));
 134 #endif /* NEVER */
 135
 136         ev->ev_next = evt->ev_next;
 137         evt->ev_next = ev;
 138     }
 139 }
 140
 141 /*
 142  * Handle the first event on the list.
 143  */
 144 void
 145 handle_timer_event(void)
 146 {
 147     time_t tm;
 148     struct event *ev = evlist;
 149     int type;
 150     struct state *st;
 151     struct connection *c = NULL;
 152     ip_address peer;
 153
 154     if (ev == (struct event *) NULL)    /* Just paranoid */
 155     {
 156         DBG(DBG_CONTROL, DBG_log("empty event list, yet we're called"));
 157         return;
 158     }
 159
 160     type = ev->ev_type;
 161     st = ev->ev_state;
 162
 163     tm = now();
 164
 165     if (tm < ev->ev_time)
 166     {
 167         DBG(DBG_CONTROL, DBG_log("called while no event expired (%lu/%lu, %s)"
 168             , (unsigned long)tm, (unsigned long)ev->ev_time
 169             , enum_show(&timer_event_names, type)));
 170
 171         /* This will happen if the most close-to-expire event was
 172          * a retransmission or cleanup, and we received a packet
 173          * at the same time as the event expired. Due to the processing
 174          * order in call_server(), the packet processing will happen first,
 175          * and the event will be removed.
 176          */
 177         return;
 178     }
 179
 180     evlist = evlist->ev_next;           /* Ok, we'll handle this event */
 181
 182     DBG(DBG_CONTROL,
 183         if (evlist != (struct event *) NULL)
 184             DBG_log("event after this is %s in %ld seconds"
 185                 , enum_show(&timer_event_names, evlist->ev_type)
 186                 , (long) (evlist->ev_time - tm)));
 187
 188     /* for state-associated events, pick up the state pointer
 189      * and remove the backpointer from the state object.
 190      * We'll eventually either schedule a new event, or delete the state.
 191      */
 192     passert(GLOBALS_ARE_RESET());
 193     if (st != NULL)
 194     {
 195         c = st->st_connection;
 196         if (type  == EVENT_DPD || type == EVENT_DPD_TIMEOUT)
 197         {
 198             passert(st->st_dpd_event == ev);
 199             st->st_dpd_event = NULL;
 200         }
 201         else
 202         {
 203             passert(st->st_event == ev);
 204             st->st_event = NULL;
 205         }
 206         peer = c->spd.that.host_addr;
 207         set_cur_state(st);
 208     }
 209
 210     switch (type)
 211     {
 212         case EVENT_REINIT_SECRET:
 213             passert(st == NULL);
 214             DBG(DBG_CONTROL, DBG_log("event EVENT_REINIT_SECRET handled"));
 215             init_secret();
 216             break;
 217
 218 #ifdef KLIPS
 219         case EVENT_SHUNT_SCAN:
 220             passert(st == NULL);
 221             scan_proc_shunts();
 222             break;
 223 #endif
 224
 225         case EVENT_LOG_DAILY:
 226             daily_log_event();
 227             break;
 228
 229         case EVENT_RETRANSMIT:
 230             /* Time to retransmit, or give up.
 231              *
 232              * Generally, we'll only try to send the message
 233              * MAXIMUM_RETRANSMISSIONS times.  Each time we double
 234              * our patience.
 235              *
 236              * As a special case, if this is the first initiating message
 237              * of a Main Mode exchange, and we have been directed to try
 238              * forever, we'll extend the number of retransmissions to
 239              * MAXIMUM_RETRANSMISSIONS_INITIAL times, with all these
 240              * extended attempts having the same patience.  The intention
 241              * is to reduce the bother when nobody is home.
 242              */
 243             {
 244                 time_t delay = 0;
 245
 246                 DBG(DBG_CONTROL, DBG_log(
 247                     "handling event EVENT_RETRANSMIT for %s \"%s\" #%lu"
 248                     , ip_str(&peer), c->name, st->st_serialno));
 249
 250                 if (st->st_retransmit < MAXIMUM_RETRANSMISSIONS)
 251                     delay = EVENT_RETRANSMIT_DELAY_0 << (st->st_retransmit + 1);
 252                 else if (st->st_state == STATE_MAIN_I1
 253                 && c->sa_keying_tries == 0
 254                 && st->st_retransmit < MAXIMUM_RETRANSMISSIONS_INITIAL)
 255                     delay = EVENT_RETRANSMIT_DELAY_0 << MAXIMUM_RETRANSMISSIONS;
 256
 257                 if (delay != 0)
 258                 {
 259                     st->st_retransmit++;
 260                     whack_log(RC_RETRANSMISSION
 261                         , "%s: retransmission; will wait %lus for response"
 262                         , enum_name(&state_names, st->st_state)
 263                         , (unsigned long)delay);
 264                     send_packet(st, "EVENT_RETRANSMIT");
 265                     event_schedule(EVENT_RETRANSMIT, delay, st);
 266                 }
 267                 else
 268                 {
 269                     /* check if we've tried rekeying enough times.
 270                      * st->st_try == 0 means that this should be the only try.
 271                      * c->sa_keying_tries == 0 means that there is no limit.
 272                      */
 273                     unsigned long try = st->st_try;
 274                     unsigned long try_limit = c->sa_keying_tries;
 275                     const char *details = "";
 276
 277                     switch (st->st_state)
 278                     {
 279                     case STATE_MAIN_I3:
 280                         details = ".  Possible authentication failure:"
 281                             " no acceptable response to our"
 282                             " first encrypted message";
 283                         break;
 284                     case STATE_MAIN_I1:
 285                         details = ".  No response (or no acceptable response) to our"
 286                             " first IKE message";
 287                         break;
 288                     case STATE_QUICK_I1:
 289                         if (c->newest_ipsec_sa == SOS_NOBODY)
 290                             details = ".  No acceptable response to our"
 291                                 " first Quick Mode message:"
 292                                 " perhaps peer likes no proposal";
 293                         break;
 294                     default:
 295                         break;
 296                     }
 297                     loglog(RC_NORETRANSMISSION
 298                         , "max number of retransmissions (%d) reached %s%s"
 299                         , st->st_retransmit
 300                         , enum_show(&state_names, st->st_state), details);
 301                     if (try != 0 && try != try_limit)
 302                     {
 303                         /* A lot like EVENT_SA_REPLACE, but over again.
 304                          * Since we know that st cannot be in use,
 305                          * we can delete it right away.
 306                          */
 307                         char story[80]; /* arbitrary limit */
 308
 309                         try++;
 310                         snprintf(story, sizeof(story), try_limit == 0
 311                             ? "starting keying attempt %ld of an unlimited number"
 312                             : "starting keying attempt %ld of at most %ld"
 313                             , try, try_limit);
 314
 315                         if (st->st_whack_sock != NULL_FD)
 316                         {
 317                             /* Release whack because the observer will get bored. */
 318                             loglog(RC_COMMENT, "%s, but releasing whack"
 319                                 , story);
 320                             release_pending_whacks(st, story);
 321                         }
 322                         else
 323                         {
 324                             /* no whack: just log to syslog */
 325                             plog("%s", story);
 326                         }
 327                         ipsecdoi_replace(st, try);
 328                     }
 329                     delete_state(st);
 330                 }
 331             }
 332             break;
 333
 334         case EVENT_SA_REPLACE:
 335         case EVENT_SA_REPLACE_IF_USED:
 336             {
 337                 so_serial_t newest = IS_PHASE1(st->st_state)
 338                     ? c->newest_isakmp_sa : c->newest_ipsec_sa;
 339
 340                 if (newest != st->st_serialno
 341                 && newest != SOS_NOBODY)
 342                 {
 343                     /* not very interesting: no need to replace */
 344                     DBG(DBG_LIFECYCLE
 345                         , plog("not replacing stale %s SA: #%lu will do"
 346                             , IS_PHASE1(st->st_state)? "ISAKMP" : "IPsec"
 347                             , newest));
 348                 }
 349                 else if (type == EVENT_SA_REPLACE_IF_USED
 350                 && st->st_outbound_time <= tm - c->sa_rekey_margin)
 351                 {
 352                     /* we observed no recent use: no need to replace
 353                      *
 354                      * The sampling effects mean that st_outbound_time
 355                      * could be up to SHUNT_SCAN_INTERVAL more recent
 356                      * than actual traffic because the sampler looks at change
 357                      * over that interval.
 358                      * st_outbound_time could also not yet reflect traffic
 359                      * in the last SHUNT_SCAN_INTERVAL.
 360                      * We expect that SHUNT_SCAN_INTERVAL is smaller than
 361                      * c->sa_rekey_margin so that the effects of this will
 362                      * be unimportant.
 363                      * This is just an optimization: correctness is not
 364                      * at stake.
 365                      *
 366                      * Note: we are abusing the DBG mechanism to control
 367                      * normal log output.
 368                      */
 369                     DBG(DBG_LIFECYCLE
 370                         , plog("not replacing stale %s SA: inactive for %lus"
 371                             , IS_PHASE1(st->st_state)? "ISAKMP" : "IPsec"
 372                             , (unsigned long)(tm - st->st_outbound_time)));
 373                 }
 374                 else
 375                 {
 376                     DBG(DBG_LIFECYCLE
 377                         , plog("replacing stale %s SA"
 378                             , IS_PHASE1(st->st_state)? "ISAKMP" : "IPsec"));
 379                     ipsecdoi_replace(st, 1);
 380                 }
 381                 delete_dpd_event(st);
 382                 event_schedule(EVENT_SA_EXPIRE, st->st_margin, st);
 383             }
 384             break;
 385
 386         case EVENT_SA_EXPIRE:
 387             {
 388                 const char *satype;
 389                 so_serial_t latest;
 390
 391                 if (IS_PHASE1(st->st_state))
 392                 {
 393                     satype = "ISAKMP";
 394                     latest = c->newest_isakmp_sa;
 395                 }
 396                 else
 397                 {
 398                     satype = "IPsec";
 399                     latest = c->newest_ipsec_sa;
 400                 }
 401
 402                 if (st->st_serialno != latest)
 403                 {
 404                     /* not very interesting: already superseded */
 405                     DBG(DBG_LIFECYCLE
 406                         , plog("%s SA expired (superseded by #%lu)"
 407                             , satype, latest));
 408                 }
 409                 else
 410                 {
 411                     plog("%s SA expired (%s)", satype
 412                         , (c->policy & POLICY_DONT_REKEY)
 413                             ? "--dontrekey"
 414                             : "LATEST!"
 415                         );
 416                 }
 417             }
 418             /* FALLTHROUGH */
 419         case EVENT_SO_DISCARD:
 420             /* Delete this state object.  It must be in the hash table. */
 421             delete_state(st);
 422             break;
 423
 424         case EVENT_DPD:
 425             dpd_outI(st);
 426             break;
 427         case EVENT_DPD_TIMEOUT:
 428             dpd_timeout(st);
 429             break;
 430 #ifdef NAT_TRAVERSAL
 431         case EVENT_NAT_T_KEEPALIVE:
 432             nat_traversal_ka_event();
 433             break;
 434 #endif
 435         default:
 436             loglog(RC_LOG_SERIOUS, "INTERNAL ERROR: ignoring unknown expiring event %s"
 437                 , enum_show(&timer_event_names, type));
 438     }
 439
 440     pfree(ev);
 441     reset_cur_state();
 442 }
 443
 444 /*
 445  * Return the time until the next event in the queue
 446  * expires (never negative), or -1 if no jobs in queue.
 447  */
 448 long
 449 next_event(void)
 450 {
 451     time_t tm;
 452
 453     if (evlist == (struct event *) NULL)
 454         return -1;
 455
 456     tm = now();
 457
 458     DBG(DBG_CONTROL,
 459         if (evlist->ev_state == NULL)
 460             DBG_log("next event %s in %ld seconds"
 461                 , enum_show(&timer_event_names, evlist->ev_type)
 462                 , (long)evlist->ev_time - (long)tm);
 463         else
 464             DBG_log("next event %s in %ld seconds for #%lu"
 465                 , enum_show(&timer_event_names, evlist->ev_type)
 466                 , (long)evlist->ev_time - (long)tm
 467                 , evlist->ev_state->st_serialno));
 468
 469     if (evlist->ev_time - tm <= 0)
 470         return 0;
 471     else
 472         return evlist->ev_time - tm;
 473 }
 474
 475 /*
 476  * Delete an event.
 477  */
 478 void
 479 delete_event(struct state *st)
 480 {
 481     if (st->st_event != (struct event *) NULL)
 482     {
 483         struct event **ev;
 484
 485         for (ev = &evlist; ; ev = &(*ev)->ev_next)
 486         {
 487             if (*ev == NULL)
 488             {
 489                 DBG(DBG_CONTROL, DBG_log("event %s to be deleted not found",
 490                     enum_show(&timer_event_names, st->st_event->ev_type)));
 491                 break;
 492             }
 493             if ((*ev) == st->st_event)
 494             {
 495                 *ev = (*ev)->ev_next;
 496
 497                 if (st->st_event->ev_type == EVENT_RETRANSMIT)
 498                     st->st_retransmit = 0;
 499                 pfree(st->st_event);
 500                 st->st_event = (struct event *) NULL;
 501
 502                 break;
 503             }
 504         }
 505     }
 506 }
 507
 508 /*
 509  * Delete a DPD event.
 510  */
 511 void
 512 delete_dpd_event(struct state *st)
 513 {
 514     if (st->st_dpd_event != (struct event *) NULL)
 515     {
 516         struct event **ev;
 517
 518         for (ev = &evlist; ; ev = &(*ev)->ev_next)
 519         {
 520             if (*ev == NULL)
 521             {
 522                 DBG(DBG_CONTROL, DBG_log("event %s to be deleted not found",
 523                     enum_show(&timer_event_names, st->st_dpd_event->ev_type)));
 524                 break;
 525             }
 526             if ((*ev) == st->st_dpd_event)
 527             {
 528                 *ev = (*ev)->ev_next;
 529                 pfree(st->st_dpd_event);
 530                 st->st_dpd_event = (struct event *) NULL;
 531                 break;
 532             }
 533         }
 534     }
 535 }
 536
 537