From: Jan Pospíšil Date: Fri, 31 Jul 2009 10:40:20 +0000 (+0000) Subject: common logging update for local logger X-Git-Tag: glite-yaim-myproxy_R_4_0_4_2~14 X-Git-Url: http://scientific.zcu.cz/git/?a=commitdiff_plain;h=e59fca2016c6f59981a85a0029b77f9d18e12af3;p=jra1mw.git common logging update for local logger --- diff --git a/org.glite.lb.logger/src/logd.c b/org.glite.lb.logger/src/logd.c index d89c2f7..d853d54 100644 --- a/org.glite.lb.logger/src/logd.c +++ b/org.glite.lb.logger/src/logd.c @@ -25,7 +25,6 @@ #endif static const char rcsid[] = "@(#)$Id$"; -static int verbose = 0; static int debug = 0; static int port = EDG_WLL_LOG_PORT_DEFAULT; static char *prefix = EDG_WLL_LOG_PREFIX_DEFAULT; @@ -45,7 +44,6 @@ extern char confirm_sock_name[256]; static struct option const long_options[] = { { "help", no_argument, 0, 'h' }, { "version", no_argument, 0, 'V' }, - { "verbose", no_argument, 0, 'v' }, { "debug", no_argument, 0, 'd' }, { "port", required_argument, 0, 'p' }, { "file-prefix", required_argument, 0, 'f' }, @@ -77,7 +75,6 @@ usage(char *program_name) { "-h, --help display this help and exit\n" "-V, --version output version information and exit\n" "-d, --debug do not run as daemon\n" - "-v, --verbose print extensive debug output\n" "-p, --port port to listen\n" "-f, --file-prefix path and prefix for event files\n" "-c, --cert location of server certificate\n" @@ -114,7 +111,7 @@ void handle_signal(int num) { if (num != SIGCHLD) glite_common_log(LOG_CATEGORY_CONTROL,LOG_PRIORITY_INFO,"Received signal %d\n", num); switch (num) { case SIGHUP: - log4c_reread(); + glite_common_log_reread(); /* TODO: probably also restart parent logd process? */ break; case SIGUSR1: @@ -188,11 +185,31 @@ doit(int socket, edg_wll_GssCred cred_handle, char *file_name_prefix, int noipc, getpeername(socket,(struct sockaddr *) &peer,&alen); glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"Accepting connection (remaining timeout %d.%06d sec)\n", (int)timeout.tv_sec, (int) timeout.tv_usec); + +/* XXX: ugly workaround, we may detect false expired certificated + * probably due to bug in Globus GSS/SSL. */ +#define _EXPIRED_CERTIFICATE_MESSAGE "certificate has expired" + if ((ret = edg_wll_gss_accept(cred_handle,socket,&timeout,&con, &gss_stat)) < 0) { glite_common_log(LOG_CATEGORY_SECURITY,LOG_PRIORITY_DEBUG,"timeout after gss_accept is %d.%06d sec\n", (int)timeout.tv_sec, (int) timeout.tv_usec); -// TODO: glite_common_log(LOG_CATEGORY_SECURITY,LOG_PRIORITY_WARN,"%s: edg_wll_gss_accept() failed\n",inet_ntoa(peer.sin_addr)); - return edg_wll_log_proto_server_failure(ret,&gss_stat,"edg_wll_gss_accept() failed\n"); + if ( ret == EDG_WLL_GSS_ERROR_TIMEOUT ) { + glite_common_log(LOG_CATEGORY_SECURITY,LOG_PRIORITY_WARN,"%s: Client authentication failed - timeout reached, closing.\n",inet_ntoa(peer.sin_addr)); + } else if (ret == EDG_WLL_GSS_ERROR_GSS) { + char *gss_err; + + edg_wll_gss_get_error(&gss_stat, "Client authentication failed", &gss_err); + if (strstr(gss_err,_EXPIRED_CERTIFICATE_MESSAGE)) { + glite_common_log(LOG_CATEGORY_SECURITY,LOG_PRIORITY_WARN,"%s: false expired certificate: %s\n",inet_ntoa(peer.sin_addr),gss_err); + free(gss_err); + return -1; + } + glite_common_log(LOG_CATEGORY_SECURITY,LOG_PRIORITY_WARN,"%s: GSS error: %s, closing.\n",inet_ntoa(peer.sin_addr),gss_err); + free(gss_err); + } else { + glite_common_log(LOG_CATEGORY_SECURITY,LOG_PRIORITY_WARN,"%s: Client authentication failed, closing.\n",inet_ntoa(peer.sin_addr)); + } + return 1; } /* authenticate */ @@ -269,10 +286,9 @@ doit(int socket, edg_wll_GssCred cred_handle, char *file_name_prefix, int noipc, } doit_end: - glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG, "Closing descriptor '%d'...",con.sock); edg_wll_gss_close(&con, NULL); if (con.sock == -1) - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_DEBUG, "o.k.\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN, "Error closing descriptor '%d'.",con.sock); if (subject) free(subject); return ret; } @@ -311,7 +327,6 @@ This is LocalLogger, part of Workload Management System in EU DataGrid & EGEE.\n while ((opt = getopt_long(argc,argv, "h" /* help */ "V" /* version */ - "v" /* verbose */ "d" /* debug */ "p:" /* port */ "f:" /* file prefix */ @@ -326,7 +341,6 @@ This is LocalLogger, part of Workload Management System in EU DataGrid & EGEE.\n switch (opt) { case 'V': fprintf(stdout,"%s:\t%s\n",argv[0],rcsid); exit(0); - case 'v': verbose = 1; break; case 'd': debug = 1; break; case 'p': port = atoi(optarg); break; case 'f': prefix = optarg; break; @@ -397,20 +411,20 @@ This is LocalLogger, part of Workload Management System in EU DataGrid & EGEE.\n } if (cred->name!=NULL) { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_INFO,"Server running with certificate: %s\n",cred->name); + glite_common_log(LOG_CATEGORY_CONTROL,LOG_PRIORITY_INFO,"Server running with certificate: %s\n",cred->name); } else if (noAuth) { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_INFO,"Server running without certificate\n"); + glite_common_log(LOG_CATEGORY_CONTROL,LOG_PRIORITY_INFO,"Server running without certificate\n"); } /* do listen */ - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_INFO,"Listening on port %d\n",port); + glite_common_log(LOG_CATEGORY_CONTROL,LOG_PRIORITY_INFO,"Listening on port %d\n",port); listener_fd = do_listen(port); if (listener_fd == -1) { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_FATAL,"Failed to listen on port %d\n",port); + glite_common_log(LOG_CATEGORY_CONTROL,LOG_PRIORITY_FATAL,"Failed to listen on port %d\n",port); edg_wll_gss_release_cred(&cred, NULL); exit(-1); } else { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_DEBUG,"Listener's socket descriptor is '%d'\n",listener_fd); + glite_common_log(LOG_CATEGORY_CONTROL,LOG_PRIORITY_DEBUG,"Listener's socket descriptor is '%d'\n",listener_fd); } client_addr_len = sizeof(client_addr); @@ -418,11 +432,11 @@ This is LocalLogger, part of Workload Management System in EU DataGrid & EGEE.\n /* daemonize */ if (debug) { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_INFO,"Running as daemon... [no]\n"); + glite_common_log(LOG_CATEGORY_CONTROL,LOG_PRIORITY_INFO,"Running as daemon... [no]\n"); } else { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_INFO,"Running as daemon... [yes]\n"); + glite_common_log(LOG_CATEGORY_CONTROL,LOG_PRIORITY_INFO,"Running as daemon... [yes]\n"); if (daemon(0,0) < 0) { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_FATAL,"Failed to run as daemon. Exiting.\n"); + glite_common_log(LOG_CATEGORY_CONTROL,LOG_PRIORITY_FATAL,"Failed to run as daemon. Exiting.\n"); SYSTEM_ERROR("daemon"); exit(1); } @@ -434,26 +448,26 @@ This is LocalLogger, part of Workload Management System in EU DataGrid & EGEE.\n while (1) { int opt; - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_INFO,"Accepting incomming connections...\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_INFO,"Accepting incomming connections...\n"); client_fd = accept(listener_fd, (struct sockaddr *) &client_addr, &client_addr_len); if (client_fd < 0) { close(listener_fd); - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_FATAL,"Failed to accept incomming connections\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_FATAL,"Failed to accept incomming connections\n"); SYSTEM_ERROR("accept"); edg_wll_gss_release_cred(&cred, NULL); exit(-1); } else { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_DEBUG,"Incomming connection on socket '%d'\n",client_fd); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"Incomming connection on socket '%d'\n",client_fd); } opt = 0; if (setsockopt(client_fd,IPPROTO_TCP,TCP_CORK,(const void *) &opt,sizeof opt)) { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_WARN,"Can't reset TCP_CORK\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"Can't reset TCP_CORK\n"); } opt = 1; if (setsockopt(client_fd,IPPROTO_TCP,TCP_NODELAY,(const void *) &opt,sizeof opt)) { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_WARN,"Can't set TCP_NODELAY\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"Can't set TCP_NODELAY\n"); } switch (edg_wll_gss_watch_creds(cert_file,&cert_mtime)) { @@ -462,15 +476,15 @@ This is LocalLogger, part of Workload Management System in EU DataGrid & EGEE.\n case 1: ret = edg_wll_gss_acquire_cred_gsi(cert_file,key_file,&newcred,&gss_stat); if (ret) { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_WARN,"Reloading credentials failed, continue with older\n"); + glite_common_log(LOG_CATEGORY_SECURITY,LOG_PRIORITY_WARN,"Reloading credentials failed, continue with older\n"); } else { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_DEBUG,"Reloading credentials succeeded\n"); + glite_common_log(LOG_CATEGORY_SECURITY,LOG_PRIORITY_DEBUG,"Reloading credentials succeeded\n"); edg_wll_gss_release_cred(&cred, NULL); cred = newcred; } break; case -1: - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_WARN,"edg_wll_gss_watch_creds failed\n"); + glite_common_log(LOG_CATEGORY_SECURITY,LOG_PRIORITY_WARN,"edg_wll_gss_watch_creds failed\n"); break; } @@ -483,12 +497,12 @@ This is LocalLogger, part of Workload Management System in EU DataGrid & EGEE.\n if (childpid == 0) { ret = doit(client_fd,cred,prefix,noIPC,noParse); if (client_fd) close(client_fd); - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_DEBUG,"Exiting.\n", + glite_common_log(LOG_CATEGORY_CONTROL,LOG_PRIORITY_DEBUG,"Exiting.\n", CONNECTION_TIMEOUT); exit(0); } if (childpid > 0) { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_DEBUG,"Forked a new child with PID %d\n",childpid); + glite_common_log(LOG_CATEGORY_CONTROL,LOG_PRIORITY_DEBUG,"Forked a new child with PID %d\n",childpid); if (client_fd) close(client_fd); } #else diff --git a/org.glite.lb.logger/src/logd_proto.c b/org.glite.lb.logger/src/logd_proto.c index 5972b4a..87a5015 100644 --- a/org.glite.lb.logger/src/logd_proto.c +++ b/org.glite.lb.logger/src/logd_proto.c @@ -40,6 +40,54 @@ int glite_common_log_priority_control; /* *---------------------------------------------------------------------- * + * handle_gss_failures - handle GSS failures on the server side + * + * Returns: errno + * + *---------------------------------------------------------------------- + */ +static int handle_gss_failures(int code, edg_wll_GssStatus *gss_code, const char *text) +{ + const char *func = "edg_wll_log_proto_server()"; + int ret = 0; + + if(code>0) { + return(0); + } + switch(code) { + case EDG_WLL_GSS_ERROR_EOF: + glite_common_log(LOG_CATEGORY_SECURITY,LOG_PRIORITY_WARN,"%s: %s, EOF occured\n", func, text); + ret = EAGAIN; + break; + case EDG_WLL_GSS_ERROR_TIMEOUT: + glite_common_log(LOG_CATEGORY_SECURITY,LOG_PRIORITY_WARN,"%s: %s, timeout expired\n", func, text); + ret = EAGAIN; + break; + case EDG_WLL_GSS_ERROR_ERRNO: + SYSTEM_ERROR(func); + glite_common_log(LOG_CATEGORY_SECURITY,LOG_PRIORITY_WARN,"%s: %s, system error occured\n", func, text); + ret = EAGAIN; + break; + case EDG_WLL_GSS_ERROR_GSS: + { + char *gss_err; + + edg_wll_gss_get_error(gss_code, "GSS error occured", &gss_err); + glite_common_log(LOG_CATEGORY_SECURITY,LOG_PRIORITY_WARN,"%s: %s, %s\n", func, text, gss_err); + free(gss_err); + ret = EAGAIN; + break; + } + default: + glite_common_log(LOG_CATEGORY_SECURITY,LOG_PRIORITY_ERROR,"%s: %s, unknown error occured\n"); + break; + } + return ret; +} + +/* + *---------------------------------------------------------------------- + * * send_answer_back - * *---------------------------------------------------------------------- @@ -51,16 +99,15 @@ static int send_answer_back(edg_wll_GssConnection *con, int answer, struct timev u_int8_t ans_end[4]; edg_wll_GssStatus gss_stat; - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_INFO,"Sending answer \"%d\" back to client...",answer); ans_end[0] = ans & 0xff; ans >>= 8; ans_end[1] = ans & 0xff; ans >>= 8; ans_end[2] = ans & 0xff; ans >>= 8; ans_end[3] = ans; if ((err = edg_wll_gss_write_full(con,ans_end,4,timeout,&count, &gss_stat)) < 0 ) { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_INFO,"error.\n"); - return edg_wll_log_proto_server_failure(err,&gss_stat,"Error sending answer"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_INFO,"Error sending answer \"%d\" back to client.\n",answer); + return handle_gss_failures(err,&gss_stat,"Error sending answer"); } else { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_INFO,"o.k.\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"Answer \"%d\" succesfully sent back to client.\n",answer); return 0; } } @@ -89,7 +136,7 @@ int init_confirmation() /* create socket */ if((confirm_sock=socket(PF_UNIX, SOCK_STREAM, 0)) < 0) { SYSTEM_ERROR("socket"); - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_ERROR,"init_confirmation(): error creating socket\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_ERROR,"init_confirmation(): error creating socket\n"); return(-1); } @@ -101,7 +148,7 @@ int init_confirmation() /* bind the socket */ if(bind(confirm_sock, (struct sockaddr *)&saddr, sizeof(saddr.sun_path)) < 0) { SYSTEM_ERROR("bind"); - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_ERROR,"init_confirmation(): error binding socket\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_ERROR,"init_confirmation(): error binding socket\n"); close(confirm_sock); unlink(confirm_sock_name); return(-1); @@ -110,7 +157,7 @@ int init_confirmation() /* and listen */ if(listen(confirm_sock, 5) < 0) { SYSTEM_ERROR("listen"); - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_ERROR,"init_confirmation(): error listening on socket\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_ERROR,"init_confirmation(): error listening on socket\n"); close(confirm_sock); unlink(confirm_sock_name); return(-1); @@ -140,7 +187,7 @@ int wait_for_confirmation(struct timeval *timeout, int *code) /* wait for confirmation at most timeout seconds */ if ((tmp=select(confirm_sock+1, &fds, NULL, NULL, timeout?&to:NULL)) < 0) { SYSTEM_ERROR("select"); - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_ERROR,"wait_for_confirmation(): error selecting socket\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_ERROR,"wait_for_confirmation(): error selecting socket\n"); ret = -1; } else { if (tmp == 0) @@ -150,12 +197,12 @@ int wait_for_confirmation(struct timeval *timeout, int *code) ret = 1; if(nsd < 0) { SYSTEM_ERROR("accept"); - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_ERROR,"wait_for_confirmation(): error accepting a connection on a socket\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_ERROR,"wait_for_confirmation(): error accepting a connection on a socket\n"); ret = -1; } else { if(recv(nsd, code, sizeof(*code), MSG_NOSIGNAL) < 0) { SYSTEM_ERROR("recv"); - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_ERROR,"wait_for_confirmation(): error receiving a message from a socket\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_ERROR,"wait_for_confirmation(): error receiving a message from a socket\n"); ret = -1; } close(nsd); @@ -203,7 +250,7 @@ int do_listen(int port) sock = socket(AF_INET, SOCK_STREAM, IPPROTO_TCP); if (sock == -1) { SYSTEM_ERROR("socket"); - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_ERROR,"do_listen(): error creating socket\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_ERROR,"do_listen(): error creating socket\n"); return -1; } @@ -211,14 +258,14 @@ int do_listen(int port) ret = bind(sock, (struct sockaddr *)&my_addr, sizeof(my_addr)); if (ret == -1) { SYSTEM_ERROR("bind"); - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_ERROR,"do_listen(): error binding socket\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_ERROR,"do_listen(): error binding socket\n"); return -1; } ret = listen(sock, 5); if (ret == -1) { SYSTEM_ERROR("listen"); - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_ERROR,"do_listen(): error listening on socket\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_ERROR,"do_listen(): error listening on socket\n"); close(sock); return -1; } @@ -270,12 +317,12 @@ int edg_wll_log_proto_server(edg_wll_GssConnection *con, struct timeval *timeout /* init */ if (edg_wll_InitContext(&context) != 0) { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_ERROR,"edg_wll_InitContex(): error.\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_ERROR,"edg_wll_InitContex(): error.\n"); answer = ENOMEM; goto edg_wll_log_proto_server_end; } if (edg_wll_ResetError(context) != 0) { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_ERROR,"edg_wll_ResetError(): error.\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_ERROR,"edg_wll_ResetError(): error.\n"); answer = ENOMEM; goto edg_wll_log_proto_server_end; } @@ -287,7 +334,7 @@ int edg_wll_log_proto_server(edg_wll_GssConnection *con, struct timeval *timeout snprintf(confirm_sock_name, sizeof(confirm_sock_name), "/tmp/dglogd_sock_%ld", lllid); if ((filedesc = open(confirm_sock_name,O_CREAT)) == -1) { if (errno == EEXIST) { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_WARN,"Warning: LLLID %ld already in use.\n",lllid); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"Warning: LLLID %ld already in use.\n",lllid); } else { SYSTEM_ERROR("open"); } @@ -298,84 +345,78 @@ int edg_wll_log_proto_server(edg_wll_GssConnection *con, struct timeval *timeout } } if (!unique) { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_ERROR,"Cannot determine the unique long local-logger id (LLLID)!\n",lllid); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_ERROR,"Cannot determine the unique long local-logger id (LLLID)!\n",lllid); return EAGAIN; } - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_INFO,"Long local-logger id (LLLID): %ld\n",lllid); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_INFO,"Long local-logger id (LLLID): %ld ... [ok]\n",lllid); /* receive socket header */ - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_INFO,"Reading socket header..."); memset(header, 0, EDG_WLL_LOG_SOCKET_HEADER_LENGTH+1); if ((err = edg_wll_gss_read_full(con, header, EDG_WLL_LOG_SOCKET_HEADER_LENGTH, timeout, &count, &gss_stat)) < 0) { if (err == EDG_WLL_GSS_ERROR_EOF) { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_INFO,"no data available.\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"Reading socket header - no data available.\n"); answer = err; answer_sent = 1; /* i.e. do not try to send answer back */ } else { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_INFO,"error.\n"); - answer = edg_wll_log_proto_server_failure(err,&gss_stat,"Error receiving header"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"Error reading socket header.\n"); + answer = handle_gss_failures(err,&gss_stat,"Error reading socket header"); } goto edg_wll_log_proto_server_end; } else { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_INFO,"o.k.\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"Reading socket header... [ok]\n"); } - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_DEBUG,"Checking socket header..."); + /* Check socket header */ header[EDG_WLL_LOG_SOCKET_HEADER_LENGTH] = '\0'; if (strncmp(header,EDG_WLL_LOG_SOCKET_HEADER,EDG_WLL_LOG_SOCKET_HEADER_LENGTH)) { /* not the proper socket header text */ - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_DEBUG,"error.\n"); - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_ERROR,"edg_wll_log_proto_server(): invalid socket header\n"); - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_DEBUG,"edg_wll_log_proto_server(): read header '%s' instead of '%s'\n", + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"edg_wll_log_proto_server(): invalid socket header\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"edg_wll_log_proto_server(): read header '%s' instead of '%s'\n", header,EDG_WLL_LOG_SOCKET_HEADER); answer = EINVAL; goto edg_wll_log_proto_server_end; } else { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_DEBUG,"o.k.\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"Read socket header: \"%s\" [ok]\n",header); } /* XXX: obsolete - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_DEBUG,"Reading message priority..."); count = 0; if ((err = edg_wll_gss_read_full(con, &priority, sizeof(priority), timeout, &count, &gss_stat)) < 0) { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_DEBUG,"error.\n"); - answer = edg_wll_log_proto_server_failure(err,&gss_stat,"Error receiving message priority"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"Error reading message priority.\n"); + answer = handle_gss_failures(err,&gss_stat,"Error receiving message priority"); goto edg_wll_log_proto_server_end; } else { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_DEBUG,"o.k.\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"Read message priority: %d [ok]\n",priority); } */ - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_DEBUG,"Reading message size..."); + /* read message size */ count = 0; if ((err = edg_wll_gss_read_full(con, size_end, 4, timeout, &count,&gss_stat)) < 0) { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_DEBUG,"error.\n"); - answer = edg_wll_log_proto_server_failure(err,&gss_stat,"Error receiving message size"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"Error reading message size.\n"); + answer = handle_gss_failures(err,&gss_stat,"Error reading message size"); goto edg_wll_log_proto_server_end; } else { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_DEBUG,"o.k.\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"Reading message size... [ok]\n"); } size = size_end[3]; size <<=8; size |= size_end[2]; size <<=8; size |= size_end[1]; size <<=8; size |= size_end[0]; - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_DEBUG,"Checking message size..."); if (size <= 0) { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_DEBUG,"error.\n"); /* probably wrong size in the header or nothing to read */ - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_ERROR,"edg_wll_log_proto_server(): invalid size read from socket header\n"); - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_DEBUG,"Read size '%d'.\n",size); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"edg_wll_log_proto_server(): invalid size read from socket header\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"Read message size '%d' [error].\n",size); answer = EINVAL; goto edg_wll_log_proto_server_end; } else { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_DEBUG,"o.k.\n"); - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_DEBUG,"- Size read from header: %d bytes.\n",size); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"Read message size: %d bytes [ok].\n",size); } /* format the DG.LLLID string */ if (asprintf(&dglllid,"DG.LLLID=%ld ",lllid) == -1) { SYSTEM_ERROR("asprintf"); - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_ERROR,"edg_wll_log_proto_server(): nomem for DG.LLLID\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"edg_wll_log_proto_server(): nomem for DG.LLLID\n"); answer = ENOMEM; goto edg_wll_log_proto_server_end; } @@ -385,7 +426,7 @@ int edg_wll_log_proto_server(edg_wll_GssConnection *con, struct timeval *timeout name_esc = glite_lbu_EscapeULM(name); if (asprintf(&dguser,"DG.USER=\"%s\" ",name_esc) == -1) { SYSTEM_ERROR("asprintf"); - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_ERROR,"edg_wll_log_proto_server(): nomem for DG.USER\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"edg_wll_log_proto_server(): nomem for DG.USER\n"); answer = ENOMEM; goto edg_wll_log_proto_server_end; } @@ -395,7 +436,7 @@ int edg_wll_log_proto_server(edg_wll_GssConnection *con, struct timeval *timeout msg_size = dglllid_size + dguser_size + size + 1; if ((msg = malloc(msg_size)) == NULL) { SYSTEM_ERROR("malloc"); - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_ERROR,"edg_wll_log_proto_server(): out of memory for allocating message\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"edg_wll_log_proto_server(): out of memory for allocating message\n"); answer = ENOMEM; goto edg_wll_log_proto_server_end; } @@ -404,52 +445,48 @@ int edg_wll_log_proto_server(edg_wll_GssConnection *con, struct timeval *timeout strncpy(msg_begin,dguser,dguser_size); /* receive message */ - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_INFO,"Reading message from socket..."); buf = msg_begin + dguser_size; count = 0; if ((err = edg_wll_gss_read_full(con, buf, size, timeout, &count, &gss_stat)) < 0) { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_INFO,"error.\n"); - answer = edg_wll_log_proto_server_failure(err,&gss_stat,"Error receiving message"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"Error reading message from socket.\n"); + answer = handle_gss_failures(err,&gss_stat,"Error reading message from socket."); goto edg_wll_log_proto_server_end; } else { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_INFO,"o.k.\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"Reading message... [ok]\n"); + // glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_TRACE,"Read message: \"%s\"\n",msg); } if (buf[count] != '\0') buf[count] = '\0'; /* parse message and get jobId and priority from it */ if (!noparse && strstr(msg, "DG.TYPE=\"command\"") == NULL) { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_INFO,"Parsing message for correctness..."); if (edg_wll_ParseEvent(context,msg_begin,&event) != 0) { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_INFO,"error.\n"); - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_ERROR,"edg_wll_log_proto_server(): edg_wll_ParseEvent error\n"); - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_ERROR,"edg_wll_ParseEvent(): %s\n",context->errDesc); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"edg_wll_log_proto_server(): edg_wll_ParseEvent error\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"edg_wll_ParseEvent(): %s\n",context->errDesc); answer = edg_wll_Error(context,NULL,NULL); goto edg_wll_log_proto_server_end; } else { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_INFO,"o.k.\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"Parsing message for correctness...[ok]\n"); } - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_DEBUG,"Getting jobId from message..."); jobId = edg_wlc_JobIdGetUnique(event->any.jobId); priority = event->any.priority; edg_wll_FreeEvent(event); event->any.priority = priority; - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_DEBUG,"o.k.\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"Getting jobId from message...[ok]\n"); } else { if ((event = edg_wll_InitEvent(EDG_WLL_EVENT_UNDEF)) == NULL) { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_ERROR, "edg_wll_InitEvent(): out of memory\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN, "edg_wll_InitEvent(): out of memory\n"); answer = ENOMEM; goto edg_wll_log_proto_server_end; } - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_DEBUG,"Getting jobId from message..."); jobId = edg_wll_GetJobId(msg); if (!jobId || edg_wlc_JobIdParse(jobId,&j)) { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_DEBUG,"error.\n"); - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_ERROR,"ParseJobId(%s)\n",jobId?jobId:"NULL"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"Error getting jobId from message.\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"edg_wlc_JobIdParse(%s)\n",jobId?jobId:"NULL"); answer = EINVAL; goto edg_wll_log_proto_server_end; } else { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_DEBUG,"o.k.\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"Getting jobId from message...[ok]\n"); } free(jobId); jobId = edg_wlc_JobIdGetUnique(j); @@ -461,41 +498,39 @@ int edg_wll_log_proto_server(edg_wll_GssConnection *con, struct timeval *timeout else event->any.priority = 0; } - /* if not command, save message to file */ if(strstr(msg, "DG.TYPE=\"command\"") == NULL) { /* compose the name of the log file */ -// glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_DEBUG,"Composing filename from prefix \"%s\" and unique jobId \"%s\"...",prefix,jobId); count = strlen(prefix); strncpy(outfilename,prefix,count); count_total=count; strncpy(outfilename+count_total,".",1); count_total+=1; count=strlen(jobId); strncpy(outfilename+count_total,jobId,count); count_total+=count; outfilename[count_total]='\0'; -// glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_DEBUG,"o.k.\n"); +// glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"Composing filename from prefix \"%s\" and unique jobId \"%s\"...[ok]",prefix,jobId); /* fopen and properly handle the filelock */ #ifdef LOGD_NOFILE - glite_common_log(LOG_CATEGORY_NAME,LOG_NOTICE,"NOT writing message to \"%s\".\n",outfilename); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_INFO,"NOT writing message to \"%s\".\n",outfilename); filepos = 0; #else - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_INFO,"Writing message to \"%s\"...",outfilename); if ( edg_wll_log_event_write(context, outfilename, msg, FCNTL_ATTEMPTS, FCNTL_TIMEOUT, &filepos) ) { char *errd; + // FIXME: there is probably not a correct errno SYSTEM_ERROR("edg_wll_log_event_write"); answer = edg_wll_Error(context, NULL, &errd); - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_ERROR,"edg_wll_log_event_write error: %s\n",errd); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"edg_wll_log_event_write error: %s\n",errd); free(errd); goto edg_wll_log_proto_server_end; - } else glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_INFO,"o.k.\n"); + } else glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_INFO,"Writing message to \"%s\"... [ok]",outfilename); #endif } else { filepos = 0; } #ifdef LB_PERF - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_INFO,"Calling perftest\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_INFO,"Calling perftest\n"); glite_wll_perftest_consumeEventString(msg); - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_INFO,"o.k.\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_INFO,"Calling perftest... [done]\n"); #endif /* if not priority send now the answer back to client */ @@ -508,47 +543,44 @@ int edg_wll_log_proto_server(edg_wll_GssConnection *con, struct timeval *timeout /* send message via IPC (UNIX socket) */ if (!noipc) { if (event->any.priority & (EDG_WLL_LOGFLAG_SYNC|EDG_WLL_LOGFLAG_SYNC_COMPAT)) { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_DEBUG,"Initializing 2nd UNIX socket (%s) for priority messages confirmation...",confirm_sock_name); if(init_confirmation() < 0) { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_DEBUG,"error.\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"Error initializing 2nd UNIX socket (%s) for priority messages confirmation.\n",confirm_sock_name); answer = errno; goto edg_wll_log_proto_server_end; } else { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_DEBUG,"o.k.\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"Initializing 2nd UNIX socket (%s) for priority messages confirmation...[ok]\n",confirm_sock_name); } } - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_DEBUG, - "Sending via IPC (UNIX socket \"%s\")\n\t" - "the message position %ld (%d bytes)", - socket_path, filepos, sizeof(filepos)); if ( edg_wll_log_event_send(context, socket_path, filepos, msg, msg_size, CONNECT_ATTEMPTS, timeout) ) { char *errd; + // FIXME: probably also not a SYSTEM ERROR SYSTEM_ERROR("edg_wll_log_event_send"); answer = edg_wll_Error(context, NULL, &errd); - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_ERROR,"edg_wll_log_event_send error: %s\n",errd); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"edg_wll_log_event_send error: %s\n",errd); free(errd); goto edg_wll_log_proto_server_end_1; - } else glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_DEBUG,"o.k.\n"); + } else glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG, + "Sending via IPC (UNIX socket \"%s\")\n\t" + "the message position %ld (%d bytes)... [ok]", + socket_path, filepos, sizeof(filepos)); if (event->any.priority & (EDG_WLL_LOGFLAG_SYNC|EDG_WLL_LOGFLAG_SYNC_COMPAT)) { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_INFO,"Waiting for confirmation..."); if ((count = wait_for_confirmation(timeout, &answer)) < 0) { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_INFO,"error.\n"); - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_ERROR,"wait_for_confirmation(): error.\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"Error waiting for confirmation.\n"); answer = errno; } else { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_INFO,"o.k.\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"Waiting for confirmation... [ok].\n"); if (count == 0) { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_DEBUG,"Waking up, timeout expired.\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"Waking up, timeout expired.\n"); answer = EAGAIN; } else { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_DEBUG,"Confirmation received, waking up.\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"Confirmation received, waking up.\n"); } } } } else { - glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_DEBUG,"NOT sending via IPC.\n"); + glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"NOT sending via IPC.\n"); } edg_wll_log_proto_server_end: @@ -565,7 +597,7 @@ edg_wll_log_proto_server_end: if (msg) free(msg); if (event) free(event); -// glite_common_log(LOG_CATEGORY_NAME,LOG_PRIORITY_INFO,"Done.\n"); +// glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_INFO,"Done.\n"); return answer; @@ -577,51 +609,3 @@ edg_wll_log_proto_server_end_1: goto edg_wll_log_proto_server_end; } -/* - *---------------------------------------------------------------------- - * - * edg_wll_log_proto_server_failure - handle protocol failures on the server side - * - * Returns: errno - * - *---------------------------------------------------------------------- - */ -int edg_wll_log_proto_server_failure(int code, edg_wll_GssStatus *gss_code, const char *text) -{ - const char *func = "edg_wll_log_proto_server()"; - int ret = 0; - - if(code>0) { - return(0); - } - switch(code) { - case EDG_WLL_GSS_ERROR_EOF: - glite_common_log(LOG_CATEGORY_SECURITY,LOG_PRIORITY_WARN,"%s: %s, EOF occured\n", func, text); - ret = EAGAIN; - break; - case EDG_WLL_GSS_ERROR_TIMEOUT: - glite_common_log(LOG_CATEGORY_SECURITY,LOG_PRIORITY_WARN,"%s: %s, timeout expired\n", func, text); - ret = EAGAIN; - break; - case EDG_WLL_GSS_ERROR_ERRNO: - SYSTEM_ERROR(func); - glite_common_log(LOG_CATEGORY_SECURITY,LOG_PRIORITY_WARN,"%s: %s, system error occured\n", func, text); - ret = EAGAIN; - break; - case EDG_WLL_GSS_ERROR_GSS: - { - char *gss_err; - - edg_wll_gss_get_error(gss_code, "GSS error occured", &gss_err); - glite_common_log(LOG_CATEGORY_SECURITY,LOG_PRIORITY_WARN,"%s: %s, %s\n", func, text, gss_err); - free(gss_err); - ret = EAGAIN; - break; - } - default: - glite_common_log(LOG_CATEGORY_SECURITY,LOG_PRIORITY_ERROR,"%s: %s, unknown error occured\n"); - break; - } - return ret; -} - diff --git a/org.glite.lb.logger/src/logd_proto.h b/org.glite.lb.logger/src/logd_proto.h index b00f72f..bdf934a 100644 --- a/org.glite.lb.logger/src/logd_proto.h +++ b/org.glite.lb.logger/src/logd_proto.h @@ -19,7 +19,6 @@ extern "C" { #include "glite/security/glite_gss.h" int edg_wll_log_proto_server(edg_wll_GssConnection *con, struct timeval *timeout, char *name, char *prefix, int noipc, int noparse); -int edg_wll_log_proto_server_failure(int code, edg_wll_GssStatus *gss_code, const char *text); /* fcntl defaults */ #define FCNTL_ATTEMPTS 5