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