experiments/clixon
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

Add process-specific logging

Browse source
This commit is contained in:
Philip Prindeville 2024-01-18 11:05:30 -07:00 • committed by Olof Hagsand
parent f923524378
commit 42a92f262a
2 changed files with 41 additions and 35 deletions
Download patch file Download diff file Expand all files Collapse all files

1
lib/clixon/clixon_debug.h
View file

@ -62,6 +62,7 @@
#define CLIXON_DBG_YANG 0x000010 /* YANG processing */ #define CLIXON_DBG_YANG 0x000010 /* YANG processing */
#define CLIXON_DBG_CLIENT 0x000020 /* App-specific */ #define CLIXON_DBG_CLIENT 0x000020 /* App-specific */
#define CLIXON_DBG_NACM 0x000040 /* NACM processing */ #define CLIXON_DBG_NACM 0x000040 /* NACM processing */
#define CLIXON_DBG_PROC 0x000080 /* Process handling */
#define CLIXON_DBG_SMASK 0x00ffff /* Subject mask */ #define CLIXON_DBG_SMASK 0x00ffff /* Subject mask */
/* /*

75
lib/src/clixon_proc.c
View file

@ -218,6 +218,8 @@ clixon_proc_socket(clixon_handle h,
goto done; goto done;
} }
clixon_debug(CLIXON_DBG_PROC, "%s...", argv[0]);
for (argc = 0; argv[argc] != NULL; ++argc) for (argc = 0; argv[argc] != NULL; ++argc)
; ;
if ((flattened = clicon_strjoin(argc, argv, "', '")) == NULL){ if ((flattened = clicon_strjoin(argc, argv, "', '")) == NULL){
@ -263,7 +265,7 @@ clixon_proc_socket(clixon_handle h,
exit(-1); /* Shouldnt reach here */ exit(-1); /* Shouldnt reach here */
} }
clixon_debug(CLIXON_DBG_DEFAULT, "child %u sock %d", child, sp[0]); clixon_debug(CLIXON_DBG_PROC | CLIXON_DBG_DETAIL, "child %u sock %d", child, sp[0]);
/* Parent */ /* Parent */
close(sp[1]); close(sp[1]);
*pid = child; *pid = child;
@ -274,6 +276,7 @@ clixon_proc_socket(clixon_handle h,
sigprocmask(SIG_SETMASK, &oset, NULL); sigprocmask(SIG_SETMASK, &oset, NULL);
set_signal(SIGINT, oldhandler, NULL); set_signal(SIGINT, oldhandler, NULL);
} }
clixon_debug(CLIXON_DBG_PROC, "retval:%d", retval);
return retval; return retval;
} }
@ -288,7 +291,7 @@ clixon_proc_socket_close(pid_t pid,
int retval = -1; int retval = -1;
int status; int status;
clixon_debug(CLIXON_DBG_DEFAULT, "pid %u sock %d", pid, sock); clixon_debug(CLIXON_DBG_PROC, "pid %u sock %d", pid, sock);
if (sock != -1) if (sock != -1)
close(sock); /* usually kills */ close(sock); /* usually kills */
@ -296,8 +299,9 @@ clixon_proc_socket_close(pid_t pid,
// usleep(100000); /* Wait for child to finish */ // usleep(100000); /* Wait for child to finish */
if(waitpid(pid, &status, 0) == pid){ if(waitpid(pid, &status, 0) == pid){
retval = WEXITSTATUS(status); retval = WEXITSTATUS(status);
clixon_debug(CLIXON_DBG_DEFAULT, "waitpid status %#x", retval); clixon_debug(CLIXON_DBG_PROC, "waitpid status %#x", retval);
} }
clixon_debug(CLIXON_DBG_PROC, "retval:%d", retval);
return retval; return retval;
} }
@ -331,7 +335,7 @@ clixon_proc_background(clixon_handle h,
char *flattened; char *flattened;
unsigned argc; unsigned argc;
clixon_debug(CLIXON_DBG_DEFAULT, ""); clixon_debug(CLIXON_DBG_PROC, "");
if (argv == NULL){ if (argv == NULL){
clixon_err(OE_UNIX, EINVAL, "argv is NULL"); clixon_err(OE_UNIX, EINVAL, "argv is NULL");
goto quit; goto quit;
@ -368,7 +372,7 @@ clixon_proc_background(clixon_handle h,
char nsfile[PATH_MAX]; char nsfile[PATH_MAX];
int nsfd; int nsfd;
#endif #endif
clixon_debug(CLIXON_DBG_DEFAULT, "child"); clixon_debug(CLIXON_DBG_PROC | CLIXON_DBG_DETAIL, "child");
clicon_signal_unblock(0); clicon_signal_unblock(0);
signal(SIGTSTP, SIG_IGN); signal(SIGTSTP, SIG_IGN);
if (chdir("/") < 0){ if (chdir("/") < 0){
@ -388,7 +392,7 @@ clixon_proc_background(clixon_handle h,
*/ */
if (netns != NULL) { if (netns != NULL) {
snprintf(nsfile, PATH_MAX, "/var/run/netns/%s", netns); /* see man setns / ip netns */ snprintf(nsfile, PATH_MAX, "/var/run/netns/%s", netns); /* see man setns / ip netns */
clixon_debug(CLIXON_DBG_DEFAULT, "nsfile:%s", nsfile); clixon_debug(CLIXON_DBG_PROC | CLIXON_DBG_DETAIL, "nsfile:%s", nsfile);
/* Change network namespace */ /* Change network namespace */
if ((nsfd = open(nsfile, O_RDONLY | O_CLOEXEC)) < 0){ if ((nsfd = open(nsfile, O_RDONLY | O_CLOEXEC)) < 0){
clixon_err(OE_UNIX, errno, "open"); clixon_err(OE_UNIX, errno, "open");
@ -427,7 +431,7 @@ clixon_proc_background(clixon_handle h,
*pid0 = child; *pid0 = child;
retval = 0; retval = 0;
quit: quit:
clixon_debug(CLIXON_DBG_DEFAULT, "retval:%d child:%u", retval, child); clixon_debug(CLIXON_DBG_PROC, "retval:%d child:%u", retval, child);
return retval; return retval;
} }
@ -532,7 +536,7 @@ clixon_process_register(clixon_handle h,
goto done; goto done;
} }
clixon_debug(CLIXON_DBG_DEFAULT, "name:%s (%s)", name, argv[0]); clixon_debug(CLIXON_DBG_PROC, "name:%s (%s)", name, argv[0]);
if ((pe = malloc(sizeof(process_entry_t))) == NULL) { if ((pe = malloc(sizeof(process_entry_t))) == NULL) {
clixon_err(OE_DB, errno, "malloc"); clixon_err(OE_DB, errno, "malloc");
@ -572,7 +576,7 @@ clixon_process_register(clixon_handle h,
} }
} }
pe->pe_callback = callback; pe->pe_callback = callback;
clixon_debug(CLIXON_DBG_DEFAULT, "%s ----> %s", clixon_debug(CLIXON_DBG_PROC | CLIXON_DBG_DETAIL, "%s ----> %s",
pe->pe_name, pe->pe_name,
clicon_int2str(proc_state_map, PROC_STATE_STOPPED) clicon_int2str(proc_state_map, PROC_STATE_STOPPED)
); );
@ -580,6 +584,7 @@ clixon_process_register(clixon_handle h,
ADDQ(pe, _proc_entry_list); ADDQ(pe, _proc_entry_list);
retval = 0; retval = 0;
done: done:
clixon_debug(CLIXON_DBG_PROC, "retval:%d", retval);
return retval; return retval;
} }
@ -711,7 +716,7 @@ clixon_process_operation(clixon_handle h,
int isrunning = 0; int isrunning = 0;
int delay = 0; int delay = 0;
clixon_debug(CLIXON_DBG_DEFAULT, "name:%s op:%s", name, clicon_int2str(proc_operation_map, op0)); clixon_debug(CLIXON_DBG_PROC, "name:%s op:%s", name, clicon_int2str(proc_operation_map, op0));
if (_proc_entry_list == NULL) if (_proc_entry_list == NULL)
goto ok; goto ok;
if ((pe = _proc_entry_list) != NULL) if ((pe = _proc_entry_list) != NULL)
@ -724,7 +729,7 @@ clixon_process_operation(clixon_handle h,
goto done; goto done;
if (op == PROC_OP_START || op == PROC_OP_STOP || op == PROC_OP_RESTART){ if (op == PROC_OP_START || op == PROC_OP_STOP || op == PROC_OP_RESTART){
pe->pe_operation = op; pe->pe_operation = op;
clixon_debug(CLIXON_DBG_DEFAULT, "scheduling name: %s pid:%d op: %s", clixon_debug(CLIXON_DBG_PROC | CLIXON_DBG_DETAIL, "scheduling name: %s pid:%d op: %s",
name, pe->pe_pid, name, pe->pe_pid,
clicon_int2str(proc_operation_map, pe->pe_operation)); clicon_int2str(proc_operation_map, pe->pe_operation));
if (pe->pe_state==PROC_STATE_RUNNING && if (pe->pe_state==PROC_STATE_RUNNING &&
@ -738,7 +743,7 @@ clixon_process_operation(clixon_handle h,
kill(pe->pe_pid, SIGTERM); kill(pe->pe_pid, SIGTERM);
delay = 1; delay = 1;
} }
clixon_debug(CLIXON_DBG_DEFAULT, "%s(%d) %s --%s--> %s", clixon_debug(CLIXON_DBG_PROC | CLIXON_DBG_DETAIL, "%s(%d) %s --%s--> %s",
pe->pe_name, pe->pe_pid, pe->pe_name, pe->pe_pid,
clicon_int2str(proc_state_map, pe->pe_state), clicon_int2str(proc_state_map, pe->pe_state),
clicon_int2str(proc_operation_map, pe->pe_operation), clicon_int2str(proc_operation_map, pe->pe_operation),
@ -749,7 +754,7 @@ clixon_process_operation(clixon_handle h,
sched++;/* start: immediate stop/restart: not immediate: wait timeout */ sched++;/* start: immediate stop/restart: not immediate: wait timeout */
} }
else{ else{
clixon_debug(CLIXON_DBG_DEFAULT, "name:%s op %s cancelled by wrap", name, clicon_int2str(proc_operation_map, op0)); clixon_debug(CLIXON_DBG_PROC | CLIXON_DBG_DETAIL, "name:%s op %s cancelled by wrap", name, clicon_int2str(proc_operation_map, op0));
} }
break; /* hit break here */ break; /* hit break here */
} }
@ -760,7 +765,7 @@ clixon_process_operation(clixon_handle h,
ok: ok:
retval = 0; retval = 0;
done: done:
clixon_debug(CLIXON_DBG_DEFAULT, "retval:%d", retval); clixon_debug(CLIXON_DBG_PROC, "retval:%d", retval);
return retval; return retval;
} }
@ -785,13 +790,13 @@ clixon_process_status(clixon_handle h,
char timestr[28]; char timestr[28];
int match = 0; int match = 0;
clixon_debug(CLIXON_DBG_DEFAULT, "name:%s", name); clixon_debug(CLIXON_DBG_PROC, "name:%s", name);
if (_proc_entry_list != NULL){ if (_proc_entry_list != NULL){
pe = _proc_entry_list; pe = _proc_entry_list;
do { do {
if (strcmp(pe->pe_name, name) == 0){ if (strcmp(pe->pe_name, name) == 0){
clixon_debug(CLIXON_DBG_DEFAULT, "found %s pid:%d", name, pe->pe_pid); clixon_debug(CLIXON_DBG_PROC | CLIXON_DBG_DETAIL, "found %s pid:%d", name, pe->pe_pid);
/* Check if running */ /* Check if running */
run = 0; run = 0;
if (pe->pe_pid && proc_op_run(pe->pe_pid, &run) < 0) if (pe->pe_pid && proc_op_run(pe->pe_pid, &run) < 0)
@ -835,7 +840,7 @@ clixon_process_status(clixon_handle h,
} }
retval = 0; retval = 0;
done: done:
clixon_debug(CLIXON_DBG_DEFAULT, "retval:%d", retval); clixon_debug(CLIXON_DBG_PROC, "retval:%d", retval);
return retval; return retval;
} }
@ -855,7 +860,7 @@ clixon_process_start_all(clixon_handle h)
proc_operation op; proc_operation op;
int sched = 0; /* If set, process action should be scheduled, register a timeout */ int sched = 0; /* If set, process action should be scheduled, register a timeout */
clixon_debug(CLIXON_DBG_DEFAULT, ""); clixon_debug(CLIXON_DBG_PROC, "");
if (_proc_entry_list == NULL) if (_proc_entry_list == NULL)
goto ok; goto ok;
pe = _proc_entry_list; pe = _proc_entry_list;
@ -866,7 +871,7 @@ clixon_process_start_all(clixon_handle h)
if (pe->pe_callback(h, pe, &op) < 0) if (pe->pe_callback(h, pe, &op) < 0)
goto done; goto done;
if (op == PROC_OP_START){ if (op == PROC_OP_START){
clixon_debug(CLIXON_DBG_DEFAULT, "name:%s start", pe->pe_name); clixon_debug(CLIXON_DBG_PROC | CLIXON_DBG_DETAIL, "name:%s start", pe->pe_name);
pe->pe_operation = op; pe->pe_operation = op;
sched++; /* Immediate dont delay for start */ sched++; /* Immediate dont delay for start */
} }
@ -877,7 +882,7 @@ clixon_process_start_all(clixon_handle h)
ok: ok:
retval = 0; retval = 0;
done: done:
clixon_debug(CLIXON_DBG_DEFAULT, "retval:%d", retval); clixon_debug(CLIXON_DBG_PROC, "retval:%d", retval);
return retval; return retval;
} }
@ -902,12 +907,12 @@ clixon_process_sched(int fd,
int isrunning; /* Process is actually running */ int isrunning; /* Process is actually running */
int sched = 0; int sched = 0;
clixon_debug(CLIXON_DBG_DEFAULT, ""); clixon_debug(CLIXON_DBG_PROC, "");
if (_proc_entry_list == NULL) if (_proc_entry_list == NULL)
goto ok; goto ok;
pe = _proc_entry_list; pe = _proc_entry_list;
do { do {
clixon_debug(CLIXON_DBG_DEFAULT, "name: %s pid:%d %s --op:%s-->", clixon_debug(CLIXON_DBG_PROC | CLIXON_DBG_DETAIL, "name: %s pid:%d %s --op:%s-->",
pe->pe_name, pe->pe_pid, clicon_int2str(proc_state_map, pe->pe_state), clicon_int2str(proc_operation_map, pe->pe_operation)); pe->pe_name, pe->pe_pid, clicon_int2str(proc_state_map, pe->pe_state), clicon_int2str(proc_operation_map, pe->pe_operation));
/* Execute pending operations and not already exiting */ /* Execute pending operations and not already exiting */
if (pe->pe_operation != PROC_OP_NONE){ if (pe->pe_operation != PROC_OP_NONE){
@ -942,7 +947,7 @@ clixon_process_sched(int fd,
pe->pe_uid, pe->pe_gid, pe->pe_fdkeep, pe->pe_uid, pe->pe_gid, pe->pe_fdkeep,
&pe->pe_pid) < 0) &pe->pe_pid) < 0)
goto done; goto done;
clixon_debug(CLIXON_DBG_DEFAULT, clixon_debug(CLIXON_DBG_PROC | CLIXON_DBG_DETAIL,
"%s(%d) %s --%s--> %s", "%s(%d) %s --%s--> %s",
pe->pe_name, pe->pe_pid, pe->pe_name, pe->pe_pid,
clicon_int2str(proc_state_map, pe->pe_state), clicon_int2str(proc_state_map, pe->pe_state),
@ -970,7 +975,7 @@ clixon_process_sched(int fd,
pe->pe_uid, pe->pe_gid, pe->pe_fdkeep, pe->pe_uid, pe->pe_gid, pe->pe_fdkeep,
&pe->pe_pid) < 0) &pe->pe_pid) < 0)
goto done; goto done;
clixon_debug(CLIXON_DBG_DEFAULT, clixon_debug(CLIXON_DBG_PROC | CLIXON_DBG_DETAIL,
"%s(%d) %s --%s--> %s", "%s(%d) %s --%s--> %s",
pe->pe_name, pe->pe_pid, pe->pe_name, pe->pe_pid,
clicon_int2str(proc_state_map, pe->pe_state), clicon_int2str(proc_state_map, pe->pe_state),
@ -994,7 +999,7 @@ clixon_process_sched(int fd,
ok: ok:
retval = 0; retval = 0;
done: done:
clixon_debug(CLIXON_DBG_DEFAULT, "retval:%d", retval); clixon_debug(CLIXON_DBG_PROC, "retval:%d", retval);
return retval; return retval;
} }
@ -1016,7 +1021,7 @@ clixon_process_sched_register(clixon_handle h,
struct timeval t; struct timeval t;
struct timeval t1 = {0, 100000}; /* 100ms */ struct timeval t1 = {0, 100000}; /* 100ms */
clixon_debug(CLIXON_DBG_DEFAULT | CLIXON_DBG_DETAIL, ""); clixon_debug(CLIXON_DBG_PROC | CLIXON_DBG_DETAIL, "");
gettimeofday(&t, NULL); gettimeofday(&t, NULL);
if (delay) if (delay)
timeradd(&t, &t1, &t); timeradd(&t, &t1, &t);
@ -1024,7 +1029,7 @@ clixon_process_sched_register(clixon_handle h,
goto done; goto done;
retval = 0; retval = 0;
done: done:
clixon_debug(CLIXON_DBG_DEFAULT | CLIXON_DBG_DETAIL, "retval:%d", retval); clixon_debug(CLIXON_DBG_PROC | CLIXON_DBG_DETAIL, "retval:%d", retval);
return retval; return retval;
} }
@ -1045,12 +1050,12 @@ clixon_process_waitpid(clixon_handle h)
int status = 0; int status = 0;
pid_t wpid; pid_t wpid;
clixon_debug(CLIXON_DBG_DEFAULT, ""); clixon_debug(CLIXON_DBG_PROC, "");
if (_proc_entry_list == NULL) if (_proc_entry_list == NULL)
goto ok; goto ok;
if ((pe = _proc_entry_list) != NULL) if ((pe = _proc_entry_list) != NULL)
do { do {
clixon_debug(CLIXON_DBG_DEFAULT, "%s(%d) %s op:%s", clixon_debug(CLIXON_DBG_PROC | CLIXON_DBG_DETAIL, "%s(%d) %s op:%s",
pe->pe_name, pe->pe_pid, pe->pe_name, pe->pe_pid,
clicon_int2str(proc_state_map, pe->pe_state), clicon_int2str(proc_state_map, pe->pe_state),
clicon_int2str(proc_operation_map, pe->pe_operation)); clicon_int2str(proc_operation_map, pe->pe_operation));
@ -1058,15 +1063,15 @@ clixon_process_waitpid(clixon_handle h)
&& (pe->pe_state == PROC_STATE_RUNNING || pe->pe_state == PROC_STATE_EXITING) && (pe->pe_state == PROC_STATE_RUNNING || pe->pe_state == PROC_STATE_EXITING)
// && (pe->pe_operation == PROC_OP_STOP || pe->pe_operation == PROC_OP_RESTART) // && (pe->pe_operation == PROC_OP_STOP || pe->pe_operation == PROC_OP_RESTART)
){ ){
clixon_debug(CLIXON_DBG_DEFAULT, "%s waitpid(%d)", clixon_debug(CLIXON_DBG_PROC | CLIXON_DBG_DETAIL, "%s waitpid(%d)",
pe->pe_name, pe->pe_pid); pe->pe_name, pe->pe_pid);
if ((wpid = waitpid(pe->pe_pid, &status, WNOHANG)) == pe->pe_pid){ if ((wpid = waitpid(pe->pe_pid, &status, WNOHANG)) == pe->pe_pid){
clixon_debug(CLIXON_DBG_DEFAULT, "waitpid(%d) waited", pe->pe_pid); clixon_debug(CLIXON_DBG_PROC | CLIXON_DBG_DETAIL, "waitpid(%d) waited", pe->pe_pid);
pe->pe_exit_status = status; pe->pe_exit_status = status;
switch (pe->pe_operation){ switch (pe->pe_operation){
case PROC_OP_NONE: /* Spontaneous / External termination */ case PROC_OP_NONE: /* Spontaneous / External termination */
case PROC_OP_STOP: case PROC_OP_STOP:
clixon_debug(CLIXON_DBG_DEFAULT, clixon_debug(CLIXON_DBG_PROC | CLIXON_DBG_DETAIL,
"%s(%d) %s --%s--> %s", "%s(%d) %s --%s--> %s",
pe->pe_name, pe->pe_pid, pe->pe_name, pe->pe_pid,
clicon_int2str(proc_state_map, pe->pe_state), clicon_int2str(proc_state_map, pe->pe_state),
@ -1085,7 +1090,7 @@ clixon_process_waitpid(clixon_handle h)
&pe->pe_pid) < 0) &pe->pe_pid) < 0)
goto done; goto done;
gettimeofday(&pe->pe_starttime, NULL); gettimeofday(&pe->pe_starttime, NULL);
clixon_debug(CLIXON_DBG_DEFAULT, "%s(%d) %s --%s--> %s", clixon_debug(CLIXON_DBG_PROC | CLIXON_DBG_DETAIL, "%s(%d) %s --%s--> %s",
pe->pe_name, pe->pe_pid, pe->pe_name, pe->pe_pid,
clicon_int2str(proc_state_map, pe->pe_state), clicon_int2str(proc_state_map, pe->pe_state),
clicon_int2str(proc_operation_map, pe->pe_operation), clicon_int2str(proc_operation_map, pe->pe_operation),
@ -1101,7 +1106,7 @@ clixon_process_waitpid(clixon_handle h)
break; /* pid is unique */ break; /* pid is unique */
} }
else else
clixon_debug(CLIXON_DBG_DEFAULT, "waitpid(%d) nomatch:%d", clixon_debug(CLIXON_DBG_PROC | CLIXON_DBG_DETAIL, "waitpid(%d) nomatch:%d",
pe->pe_pid, wpid); pe->pe_pid, wpid);
} }
pe = NEXTQ(process_entry_t *, pe); pe = NEXTQ(process_entry_t *, pe);
@ -1109,7 +1114,7 @@ clixon_process_waitpid(clixon_handle h)
ok: ok:
retval = 0; retval = 0;
done: done:
clixon_debug(CLIXON_DBG_DEFAULT, "retval:%d", retval); clixon_debug(CLIXON_DBG_PROC, "retval:%d", retval);
return retval; return retval;
} }