Raise priority of error messages when cannot open a socket
[trust_router.git] / tid / tids.c
index 36d4e68..c1c9bcb 100644 (file)
@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2012, JANET(UK)
+ * Copyright (c) 2012, 2015, JANET(UK)
  * All rights reserved.
  *
  * Redistribution and use in source and binary forms, with or without
 #include <assert.h>
 #include <stdlib.h>
 #include <unistd.h>
+#include <fcntl.h>
 #include <string.h>
 #include <stdio.h>
 #include <errno.h>
 #include <sys/socket.h>
+#include <sys/wait.h>
 #include <netinet/in.h>
 #include <jansson.h>
 #include <talloc.h>
+#include <poll.h>
 #include <tid_internal.h>
 #include <gsscon.h>
+#include <tr_debug.h>
 #include <tr_msg.h>
 
 static TID_RESP *tids_create_response (TIDS_INSTANCE *tids, TID_REQ *req) 
 {
-  TID_RESP *resp;
+  TID_RESP *resp=NULL;
+  int success=0;
 
-  if ((NULL == (resp = talloc_zero(req, TID_RESP)))) {
-    fprintf(stderr, "tids_create_response: Error allocating response structure.\n");
+  if (NULL == (resp = tid_resp_new(req))) {
+    tr_crit("tids_create_response: Error allocating response structure.");
     return NULL;
   }
   
@@ -59,78 +64,124 @@ static TID_RESP *tids_create_response (TIDS_INSTANCE *tids, TID_REQ *req)
   if ((NULL == (resp->rp_realm = tr_dup_name(req->rp_realm))) ||
       (NULL == (resp->realm = tr_dup_name(req->realm))) ||
       (NULL == (resp->comm = tr_dup_name(req->comm)))) {
-    fprintf(stderr, "tids_create_response: Error allocating fields in response.\n");
-    return NULL;
+    tr_crit("tids_create_response: Error allocating fields in response.");
+    goto cleanup;
   }
   if (req->orig_coi) {
     if (NULL == (resp->orig_coi = tr_dup_name(req->orig_coi))) {
-      fprintf(stderr, "tids_create_response: Error allocating fields in response.\n");
-      return NULL;
+      tr_crit("tids_create_response: Error allocating fields in response.");
+      goto cleanup;
     }
   }
-  return resp;
-}
 
-static void tids_destroy_response(TIDS_INSTANCE *tids, TID_RESP *resp) 
-{
-  if (resp) {
-    if (resp->err_msg)
-      tr_free_name(resp->err_msg);
-    if (resp->rp_realm)
-      tr_free_name(resp->rp_realm);
-    if (resp->realm)
-      tr_free_name(resp->realm);
-    if (resp->comm)
-      tr_free_name(resp->comm);
-    if (resp->orig_coi)
-      tr_free_name(resp->orig_coi);
+  success=1;
+
+cleanup:
+  if ((!success) && (resp!=NULL)) {
     talloc_free(resp);
+    resp=NULL;
   }
+  return resp;
 }
 
-static int tids_listen (TIDS_INSTANCE *tids, int port
+static int tids_listen(TIDS_INSTANCE *tids, int port, int *fd_out, size_t max_fd
 {
-    int rc = 0;
-    int conn = -1;
-    int optval = 1;
+  int rc = 0;
+  int conn = -1;
+  int optval = 1;
+  struct addrinfo *ai=NULL;
+  struct addrinfo *ai_head=NULL;
+  struct addrinfo hints={.ai_flags=AI_PASSIVE,
+                         .ai_family=AF_UNSPEC,
+                         .ai_socktype=SOCK_STREAM,
+                         .ai_protocol=IPPROTO_TCP};
+  char *port_str=NULL;
+  size_t n_opened=0;
+
+  tr_debug("tids_listen: started!");
+  port_str=talloc_asprintf(NULL, "%d", port);
+  if (port_str==NULL) {
+    tr_debug("tids_listen: unable to allocate port.");
+    return -1;
+  }
 
-    union {
-      struct sockaddr_storage storage;
-      struct sockaddr_in in4;
-    } addr;
+  tr_debug("getaddrinfo()=%d", getaddrinfo(NULL, port_str, &hints, &ai_head));
+  talloc_free(port_str);
+  tr_debug("tids_listen: got address info");
 
-    struct sockaddr_in *saddr = (struct sockaddr_in *) &addr.in4;
-    
-    saddr->sin_port = htons (port);
-    saddr->sin_family = AF_INET;
-    saddr->sin_addr.s_addr = INADDR_ANY;
-
-    if (0 > (conn = socket (AF_INET, SOCK_STREAM, 0)))
-      return conn;
-        
-    setsockopt(conn, SOL_SOCKET, SO_REUSEADDR, &optval, sizeof(optval));
-
-    if (0 > (rc = bind (conn, (struct sockaddr *) saddr, sizeof(struct sockaddr_in))))
-      return rc;
-        
-    if (0 > (rc = listen(conn, 512)))
-      return rc;
-    
-    fprintf (stdout, "tids_listen: TID Server listening on port %d\n", port);
-    return conn; 
+  /* TODO: listen on all ports */
+  for (ai=ai_head,n_opened=0; (ai!=NULL)&&(n_opened<max_fd); ai=ai->ai_next) {
+    if (0 > (conn = socket(ai->ai_family, ai->ai_socktype, ai->ai_protocol))) {
+      tr_debug("tids_listen: unable to open socket.");
+      continue;
+    }
+
+    optval=1;
+    if (0!=setsockopt(conn, SOL_SOCKET, SO_REUSEADDR, &optval, sizeof(optval)))
+      tr_debug("tids_listen: unable to set SO_REUSEADDR."); /* not fatal? */
+
+    if (ai->ai_family==AF_INET6) {
+      /* don't allow IPv4-mapped IPv6 addresses (per RFC4942, not sure
+       * if still relevant) */
+      if (0!=setsockopt(conn, IPPROTO_IPV6, IPV6_V6ONLY, &optval, sizeof(optval))) {
+        tr_debug("tids_listen: unable to set IPV6_V6ONLY. Skipping interface.");
+        close(conn);
+        continue;
+      }
+    }
+
+    rc=bind(conn, ai->ai_addr, ai->ai_addrlen);
+    if (rc<0) {
+      tr_debug("tids_listen: unable to bind to socket.");
+      close(conn);
+      continue;
+    }
+
+    if (0>listen(conn, 512)) {
+      tr_debug("tids_listen: unable to listen on bound socket.");
+      close(conn);
+      continue;
+    }
+
+    /* ok, this one worked. Save it */
+    fd_out[n_opened++]=conn;
+  }
+  freeaddrinfo(ai_head);
+
+  if (n_opened==0) {
+    tr_debug("tids_listen: no addresses available for listening.");
+    return -1;
+  }
+
+  tr_debug("tids_listen: TRP Server listening on port %d on %d socket%s",
+           port,
+           n_opened,
+           (n_opened==1)?"":"s");
+
+  return n_opened;
 }
 
+/* returns EACCES if authorization is denied */
 static int tids_auth_cb(gss_name_t clientName, gss_buffer_t displayName,
                        void *data)
 {
   struct tids_instance *inst = (struct tids_instance *) data;
   TR_NAME name ={(char *) displayName->value,
                 displayName->length};
-  return inst->auth_handler(clientName, &name, inst->cookie);
+  int result=0;
+
+  if (0!=inst->auth_handler(clientName, &name, inst->cookie)) {
+    tr_debug("tids_auth_cb: client '%.*s' denied authorization.", name.len, name.buf);
+    result=EACCES; /* denied */
+  }
+
+  return result;
 }
 
-static int tids_auth_connection (struct tids_instance *inst,
-                                int conn, gss_ctx_id_t *gssctx)
+/* returns 0 on authorization success, 1 on failure, or -1 in case of error */
+static int tids_auth_connection (TIDS_INSTANCE *inst,
+                                int conn,
+                                 gss_ctx_id_t *gssctx)
 {
   int rc = 0;
   int auth, autherr = 0;
@@ -141,22 +192,25 @@ static int tids_auth_connection (struct tids_instance *inst,
   nameLen = asprintf(&name, "trustidentity@%s", inst->hostname);
   nameBuffer.length = nameLen;
   nameBuffer.value = name;
-  
+
   if (rc = gsscon_passive_authenticate(conn, nameBuffer, gssctx, tids_auth_cb, inst)) {
-    fprintf(stderr, "tids_auth_connection: Error from gsscon_passive_authenticate(), rc = %d.\n", rc);
+    tr_debug("tids_auth_connection: Error from gsscon_passive_authenticate(), rc = %d.", rc);
+    free(name);
     return -1;
   }
+  free(name);
+  nameBuffer.value=NULL; nameBuffer.length=0;
 
   if (rc = gsscon_authorize(*gssctx, &auth, &autherr)) {
-    fprintf(stderr, "tids_auth_connection: Error from gsscon_authorize, rc = %d, autherr = %d.\n", 
+    tr_debug("tids_auth_connection: Error from gsscon_authorize, rc = %d, autherr = %d.", 
            rc, autherr);
     return -1;
   }
 
   if (auth)
-    fprintf(stdout, "tids_auth_connection: Connection authenticated, conn = %d.\n", conn);
+    tr_debug("tids_auth_connection: Connection authenticated, conn = %d.", conn);
   else
-    fprintf(stderr, "tids_auth_connection: Authentication failed, conn %d.\n", conn);
+    tr_debug("tids_auth_connection: Authentication failed, conn %d.", conn);
 
   return !auth;
 }
@@ -173,18 +227,18 @@ static int tids_read_request (TIDS_INSTANCE *tids, int conn, gss_ctx_id_t *gssct
     return -1;
   }
 
-  fprintf(stdout, "tids_read_request():Request Received, %u bytes.\n", (unsigned) buflen);
+  tr_debug("tids_read_request():Request Received, %u bytes.", (unsigned) buflen);
 
   /* Parse request */
   if (NULL == ((*mreq) = tr_msg_decode(buf, buflen))) {
-    fprintf(stderr, "tids_read_request():Error decoding request.\n");
+    tr_debug("tids_read_request():Error decoding request.");
     free (buf);
     return -1;
   }
 
   /* If this isn't a TID Request, just drop it. */
   if (TID_REQUEST != (*mreq)->msg_type) {
-    fprintf(stderr, "tids_read_request(): Not a TID Request, dropped.\n");
+    tr_debug("tids_read_request(): Not a TID Request, dropped.");
     return -1;
   }
 
@@ -194,29 +248,34 @@ static int tids_read_request (TIDS_INSTANCE *tids, int conn, gss_ctx_id_t *gssct
 
 static int tids_handle_request (TIDS_INSTANCE *tids, TR_MSG *mreq, TID_RESP *resp) 
 {
-  int rc;
+  int rc=-1;
 
   /* Check that this is a valid TID Request.  If not, send an error return. */
-  if ((!mreq->tid_req) ||
-      (!mreq->tid_req->rp_realm) ||
-      (!mreq->tid_req->realm) ||
-      (!mreq->tid_req->comm)) {
-    fprintf(stderr, "tids_handle_request():Not a valid TID Request.\n");
+  if ((!tr_msg_get_req(mreq)) ||
+      (!tr_msg_get_req(mreq)->rp_realm) ||
+      (!tr_msg_get_req(mreq)->realm) ||
+      (!tr_msg_get_req(mreq)->comm)) {
+    tr_notice("tids_handle_request(): Not a valid TID Request.");
     resp->result = TID_ERROR;
     resp->err_msg = tr_new_name("Bad request format");
     return -1;
   }
 
+  tr_debug("tids_handle_request: adding self to req path.");
+  tid_req_add_path(tr_msg_get_req(mreq), tids->hostname, tids->tids_port);
+  
   /* Call the caller's request handler */
   /* TBD -- Handle different error returns/msgs */
-  if (0 > (rc = (*tids->req_handler)(tids, mreq->tid_req, resp, tids->cookie))) {
+  if (0 > (rc = (*tids->req_handler)(tids, tr_msg_get_req(mreq), resp, tids->cookie))) {
     /* set-up an error response */
+    tr_debug("tids_handle_request: req_handler returned error.");
     resp->result = TID_ERROR;
     if (!resp->err_msg)        /* Use msg set by handler, if any */
       resp->err_msg = tr_new_name("Internal processing error");
   }
   else {
     /* set-up a success response */
+    tr_debug("tids_handle_request: req_handler returned success.");
     resp->result = TID_SUCCESS;
     resp->err_msg = NULL;      /* No error msg on successful return */
   }
@@ -233,17 +292,18 @@ int tids_send_err_response (TIDS_INSTANCE *tids, TID_REQ *req, const char *err_m
     return 0;
 
   if (NULL == (resp = tids_create_response(tids, req))) {
-    fprintf(stderr, "tids_send_err_response: Can't create response.\n");
+    tr_crit("tids_send_err_response: Can't create response.");
     return -1;
   }
-
+  
   /* mark this as an error response, and include the error message */
   resp->result = TID_ERROR;
   resp->err_msg = tr_new_name((char *)err_msg);
+  resp->error_path = req->path;
 
   rc = tids_send_response(tids, req, resp);
   
-  tids_destroy_response(tids, resp);
+  tid_resp_free(resp);
   return rc;
 }
 
@@ -254,26 +314,36 @@ int tids_send_response (TIDS_INSTANCE *tids, TID_REQ *req, TID_RESP *resp)
   char *resp_buf;
 
   if ((!tids) || (!req) || (!resp))
-    fprintf (stderr, "tids_send_response: Invalid parameters.\n");
+    tr_debug("tids_send_response: Invalid parameters.");
 
   /* Never send a second response if we already sent one. */
   if (req->resp_sent)
     return 0;
 
   mresp.msg_type = TID_RESPONSE;
-  mresp.tid_resp = resp;
-  
+  tr_msg_set_resp(&mresp, resp);
+
   if (NULL == (resp_buf = tr_msg_encode(&mresp))) {
-    fprintf(stderr, "tids_send_response: Error encoding json response.\n");
+
+    tr_err("tids_send_response: Error encoding json response.");
+    tr_audit_req(req);
+
     return -1;
   }
 
-  fprintf(stderr, "tids_send_response: Encoded response:\n%s\n", resp_buf);
-  
+  tr_debug("tids_send_response: Encoded response: %s", resp_buf);
+
+  /* If external logging is enabled, fire off a message */
+  /* TODO Can be moved to end once segfault in gsscon_write_encrypted_token fixed */
+  tr_audit_resp(resp);
+
   /* Send the response over the connection */
   if (err = gsscon_write_encrypted_token (req->conn, req->gssctx, resp_buf, 
                                          strlen(resp_buf) + 1)) {
-    fprintf(stderr, "tids_send_response: Error sending response over connection.\n");
+    tr_notice("tids_send_response: Error sending response over connection.");
+
+    tr_audit_req(req);
+
     return -1;
   }
 
@@ -293,109 +363,201 @@ static void tids_handle_connection (TIDS_INSTANCE *tids, int conn)
   gss_ctx_id_t gssctx = GSS_C_NO_CONTEXT;
 
   if (tids_auth_connection(tids, conn, &gssctx)) {
-    fprintf(stderr, "tids_handle_connection: Error authorizing TID Server connection.\n");
+    tr_notice("tids_handle_connection: Error authorizing TID Server connection.");
     close(conn);
     return;
   }
 
-  fprintf(stdout, "tids_handle_connection: Connection authorized!\n");
+  tr_debug("tids_handle_connection: Connection authorized!");
 
   while (1) {  /* continue until an error breaks us out */
 
     if (0 > (rc = tids_read_request(tids, conn, &gssctx, &mreq))) {
-      fprintf(stderr, "tids_handle_connection: Error from tids_read_request(), rc = %d.\n", rc);
+      tr_debug("tids_handle_connection: Error from tids_read_request(), rc = %d.", rc);
       return;
     } else if (0 == rc) {
       continue;
     }
 
     /* Put connection information into the request structure */
-    mreq->tid_req->conn = conn;
-    mreq->tid_req->gssctx = gssctx;
+    tr_msg_get_req(mreq)->conn = conn;
+    tr_msg_get_req(mreq)->gssctx = gssctx;
 
     /* Allocate a response structure and populate common fields */
-    if (NULL == (resp = tids_create_response (tids, mreq->tid_req))) {
-      fprintf(stderr, "tids_handle_connection: Error creating response structure.\n");
+    if (NULL == (resp = tids_create_response (tids, tr_msg_get_req(mreq)))) {
+      tr_crit("tids_handle_connection: Error creating response structure.");
       /* try to send an error */
-      tids_send_err_response(tids, mreq->tid_req, "Error creating response.\n");
+      tids_send_err_response(tids, tr_msg_get_req(mreq), "Error creating response.");
+      tr_msg_free_decoded(mreq);
       return;
     }
 
     if (0 > (rc = tids_handle_request(tids, mreq, resp))) {
-      fprintf(stderr, "tids_handle_connection: Error from tids_handle_request(), rc = %d.\n", rc);
+      tr_debug("tids_handle_connection: Error from tids_handle_request(), rc = %d.", rc);
       /* Fall through, to send the response, either way */
     }
 
-    if (0 > (rc = tids_send_response(tids, mreq->tid_req, resp))) {
-      fprintf(stderr, "tids_handle_connection: Error from tids_send_response(), rc = %d.\n", rc);
+    if (0 > (rc = tids_send_response(tids, tr_msg_get_req(mreq), resp))) {
+      tr_debug("tids_handle_connection: Error from tids_send_response(), rc = %d.", rc);
       /* if we didn't already send a response, try to send a generic error. */
-      if (!mreq->tid_req->resp_sent)
-       tids_send_err_response(tids, mreq->tid_req, "Error sending response.\n");
+      if (!tr_msg_get_req(mreq)->resp_sent)
+        tids_send_err_response(tids, tr_msg_get_req(mreq), "Error sending response.");
       /* Fall through to free the response, either way. */
     }
     
-    tids_destroy_response(tids, resp);
+    tr_msg_free_decoded(mreq); /* takes resp with it */
     return;
   } 
 }
 
 TIDS_INSTANCE *tids_create (void)
 {
-  TIDS_INSTANCE *tids = NULL;
-  if (tids = malloc(sizeof(TIDS_INSTANCE)))
-    memset(tids, 0, sizeof(TIDS_INSTANCE));
-  return tids;
+  return talloc_zero(NULL, TIDS_INSTANCE);
+}
+
+/* Get a listener for tids requests, returns its socket fd. Accept
+ * connections with tids_accept() */
+int tids_get_listener(TIDS_INSTANCE *tids, 
+                      TIDS_REQ_FUNC *req_handler,
+                      tids_auth_func *auth_handler,
+                      const char *hostname,
+                      unsigned int port,
+                      void *cookie,
+                      int *fd_out,
+                      size_t max_fd)
+{
+  size_t n_fd=0;
+  size_t ii=0;
+
+  tids->tids_port = port;
+  n_fd=tids_listen(tids, port, fd_out, max_fd);
+  if (n_fd<=0)
+    tr_err("tids_get_listener: Error opening port %d");
+  else {
+    /* opening port succeeded */
+    tr_info("tids_get_listener: Opened port %d.", port);
+    
+    /* make this socket non-blocking */
+    for (ii=0; ii<n_fd; ii++) {
+      if (0 != fcntl(fd_out[ii], F_SETFL, O_NONBLOCK)) {
+        tr_err("tids_get_listener: Error setting O_NONBLOCK.");
+        for (ii=0; ii<n_fd; ii++) {
+          close(fd_out[ii]);
+          fd_out[ii]=-1;
+        }
+        n_fd=0;
+        break;
+      }
+    }
+  }
+
+  if (n_fd>0) {
+    /* store the caller's request handler & cookie */
+    tids->req_handler = req_handler;
+    tids->auth_handler = auth_handler;
+    tids->hostname = hostname;
+    tids->cookie = cookie;
+  }
+
+  return n_fd;
+}
+
+/* Accept and process a connection on a port opened with tids_get_listener() */
+int tids_accept(TIDS_INSTANCE *tids, int listen)
+{
+  int conn=-1;
+  int pid=-1;
+
+  if (0 > (conn = accept(listen, NULL, NULL))) {
+    perror("Error from TIDS Server accept()");
+    return 1;
+  }
+
+  if (0 > (pid = fork())) {
+    perror("Error on fork()");
+    return 1;
+  }
+
+  if (pid == 0) {
+    close(listen);
+    tids_handle_connection(tids, conn);
+    close(conn);
+    exit(0); /* exit to kill forked child process */
+  } else {
+    close(conn);
+  }
+
+  /* clean up any processes that have completed  (TBD: move to main loop?) */
+  while (waitpid(-1, 0, WNOHANG) > 0);
+
+  return 0;
 }
 
+/* Process tids requests forever. Should not return except on error. */
+#define MAX_SOCKETS 10
 int tids_start (TIDS_INSTANCE *tids, 
-               TIDS_REQ_FUNC *req_handler,
-               tids_auth_func *auth_handler,
-               const char *hostname,
-               unsigned int port,
-               void *cookie)
+                TIDS_REQ_FUNC *req_handler,
+                tids_auth_func *auth_handler,
+                const char *hostname,
+                unsigned int port,
+                void *cookie)
 {
-  int listen = -1;
-  int conn = -1;
-  pid_t pid;
+  int fd[MAX_SOCKETS]={0};
+  size_t n_fd=0;
+  struct pollfd poll_fd[MAX_SOCKETS]={{0}};
+  int ii=0;
 
-  if (0 > (listen = tids_listen(tids, port)))
+  n_fd=tids_get_listener(tids, req_handler, auth_handler, hostname, port, cookie, fd, MAX_SOCKETS);
+  if (n_fd <= 0) {
     perror ("Error from tids_listen()");
+    return 1;
+  }
 
-  /* store the caller's request handler & cookie */
-  tids->req_handler = req_handler;
-  tids->auth_handler = auth_handler;
-  tids->hostname = hostname;
-  tids->cookie = cookie;
+  tr_info("Trust Path Query Server starting on host %s:%d.", hostname, port);
+
+  /* set up the poll structs */
+  for (ii=0; ii<n_fd; ii++) {
+    poll_fd[ii].fd=fd[ii];
+    poll_fd[ii].events=POLLIN;
+  }
 
   while(1) {   /* accept incoming conns until we are stopped */
+    /* clear out events from previous iteration */
+    for (ii=0; ii<n_fd; ii++)
+      poll_fd[ii].revents=0;
 
-    if (0 > (conn = accept(listen, NULL, NULL))) {
-      perror("Error from TIDS Server accept()");
+    /* wait indefinitely for a connection */
+    if (poll(poll_fd, n_fd, -1) < 0) {
+      perror("Error from poll()");
       return 1;
     }
 
-    if (0 > (pid = fork())) {
-      perror("Error on fork()");
-      return 1;
-    }
+    /* fork handlers for any sockets that have data */
+    for (ii=0; ii<n_fd; ii++) {
+      if (poll_fd[ii].revents == 0)
+        continue;
 
-    if (pid == 0) {
-      close(listen);
-      tids_handle_connection(tids, conn);
-      close(conn);
-      return 0;
-    } else {
-      close(conn);
+      if ((poll_fd[ii].revents & POLLERR) || (poll_fd[ii].revents & POLLNVAL)) {
+        perror("Error polling fd");
+        continue;
+      }
+
+      if (poll_fd[ii].revents & POLLIN) {
+        if (tids_accept(tids, poll_fd[ii].fd))
+          tr_err("tids_start: error in tids_accept().");
+      }
     }
   }
 
-  return 1;    /* should never get here */
+  return 1;    /* should never get here, loops "forever" */
 }
+#undef MAX_SOCKETS
 
 void tids_destroy (TIDS_INSTANCE *tids)
 {
+  /* clean up logfiles */
+  tr_log_close();
+
   if (tids)
     free(tids);
 }
-
-