Skip to content

Commit

Permalink
Add process-specific logging
Browse files Browse the repository at this point in the history
  • Loading branch information
Philip Prindeville committed Jan 18, 2024
1 parent 57ff490 commit af55bf1
Show file tree
Hide file tree
Showing 2 changed files with 41 additions and 35 deletions.
1 change: 1 addition & 0 deletions lib/clixon/clixon_debug.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -62,6 +62,7 @@
#define CLIXON_DBG_YANG 0x000010 /* YANG processing */
#define CLIXON_DBG_CLIENT 0x000020 /* App-specific */
#define CLIXON_DBG_NACM 0x000040 /* NACM processing */
#define CLIXON_DBG_PROC 0x000080 /* Process handling */
#define CLIXON_DBG_SMASK 0x00ffff /* Subject mask */

/*
Expand Down
75 changes: 40 additions & 35 deletions lib/src/clixon_proc.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -218,6 +218,8 @@ clixon_proc_socket(clixon_handle h,
goto done;
}

clixon_debug(CLIXON_DBG_PROC, "%s...", argv[0]);

for (argc = 0; argv[argc] != NULL; ++argc)
;
if ((flattened = clicon_strjoin(argc, argv, "', '")) == NULL){
Expand Down Expand Up @@ -263,7 +265,7 @@ clixon_proc_socket(clixon_handle h,
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 */
close(sp[1]);
*pid = child;
Expand All @@ -274,6 +276,7 @@ clixon_proc_socket(clixon_handle h,
sigprocmask(SIG_SETMASK, &oset, NULL);
set_signal(SIGINT, oldhandler, NULL);
}
clixon_debug(CLIXON_DBG_PROC, "retval:%d", retval);
return retval;
}

Expand All @@ -288,16 +291,17 @@ clixon_proc_socket_close(pid_t pid,
int retval = -1;
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)
close(sock); /* usually kills */
kill(pid, SIGTERM);
// usleep(100000); /* Wait for child to finish */
if(waitpid(pid, &status, 0) == pid){
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;
}

Expand Down Expand Up @@ -331,7 +335,7 @@ clixon_proc_background(clixon_handle h,
char *flattened;
unsigned argc;

clixon_debug(CLIXON_DBG_DEFAULT, "");
clixon_debug(CLIXON_DBG_PROC, "");
if (argv == NULL){
clixon_err(OE_UNIX, EINVAL, "argv is NULL");
goto quit;
Expand Down Expand Up @@ -368,7 +372,7 @@ clixon_proc_background(clixon_handle h,
char nsfile[PATH_MAX];
int nsfd;
#endif
clixon_debug(CLIXON_DBG_DEFAULT, "child");
clixon_debug(CLIXON_DBG_PROC | CLIXON_DBG_DETAIL, "child");
clicon_signal_unblock(0);
signal(SIGTSTP, SIG_IGN);
if (chdir("/") < 0){
Expand All @@ -388,7 +392,7 @@ clixon_proc_background(clixon_handle h,
*/
if (netns != NULL) {
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 */
if ((nsfd = open(nsfile, O_RDONLY | O_CLOEXEC)) < 0){
clixon_err(OE_UNIX, errno, "open");
Expand Down Expand Up @@ -427,7 +431,7 @@ clixon_proc_background(clixon_handle h,
*pid0 = child;
retval = 0;
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;
}

Expand Down Expand Up @@ -532,7 +536,7 @@ clixon_process_register(clixon_handle h,
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) {
clixon_err(OE_DB, errno, "malloc");
Expand Down Expand Up @@ -572,14 +576,15 @@ clixon_process_register(clixon_handle h,
}
}
pe->pe_callback = callback;
clixon_debug(CLIXON_DBG_DEFAULT, "%s ----> %s",
clixon_debug(CLIXON_DBG_PROC | CLIXON_DBG_DETAIL, "%s ----> %s",
pe->pe_name,
clicon_int2str(proc_state_map, PROC_STATE_STOPPED)
);
pe->pe_state = PROC_STATE_STOPPED;
ADDQ(pe, _proc_entry_list);
retval = 0;
done:
clixon_debug(CLIXON_DBG_PROC, "retval=%d", retval);
return retval;
}

Expand Down Expand Up @@ -711,7 +716,7 @@ clixon_process_operation(clixon_handle h,
int isrunning = 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)
goto ok;
if ((pe = _proc_entry_list) != NULL)
Expand All @@ -724,7 +729,7 @@ clixon_process_operation(clixon_handle h,
goto done;
if (op == PROC_OP_START || op == PROC_OP_STOP || op == PROC_OP_RESTART){
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,
clicon_int2str(proc_operation_map, pe->pe_operation));
if (pe->pe_state==PROC_STATE_RUNNING &&
Expand All @@ -738,7 +743,7 @@ clixon_process_operation(clixon_handle h,
kill(pe->pe_pid, SIGTERM);
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,
clicon_int2str(proc_state_map, pe->pe_state),
clicon_int2str(proc_operation_map, pe->pe_operation),
Expand All @@ -749,7 +754,7 @@ clixon_process_operation(clixon_handle h,
sched++;/* start: immediate stop/restart: not immediate: wait timeout */
}
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 */
}
Expand All @@ -760,7 +765,7 @@ clixon_process_operation(clixon_handle h,
ok:
retval = 0;
done:
clixon_debug(CLIXON_DBG_DEFAULT, "retval:%d", retval);
clixon_debug(CLIXON_DBG_PROC, "retval:%d", retval);
return retval;
}

Expand All @@ -785,13 +790,13 @@ clixon_process_status(clixon_handle h,
char timestr[28];
int match = 0;

clixon_debug(CLIXON_DBG_DEFAULT, "name:%s", name);
clixon_debug(CLIXON_DBG_PROC, "name:%s", name);

if (_proc_entry_list != NULL){
pe = _proc_entry_list;
do {
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 */
run = 0;
if (pe->pe_pid && proc_op_run(pe->pe_pid, &run) < 0)
Expand Down Expand Up @@ -835,7 +840,7 @@ clixon_process_status(clixon_handle h,
}
retval = 0;
done:
clixon_debug(CLIXON_DBG_DEFAULT, "retval:%d", retval);
clixon_debug(CLIXON_DBG_PROC, "retval:%d", retval);
return retval;
}

Expand All @@ -855,7 +860,7 @@ clixon_process_start_all(clixon_handle h)
proc_operation op;
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)
goto ok;
pe = _proc_entry_list;
Expand All @@ -866,7 +871,7 @@ clixon_process_start_all(clixon_handle h)
if (pe->pe_callback(h, pe, &op) < 0)
goto done;
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;
sched++; /* Immediate dont delay for start */
}
Expand All @@ -877,7 +882,7 @@ clixon_process_start_all(clixon_handle h)
ok:
retval = 0;
done:
clixon_debug(CLIXON_DBG_DEFAULT, "retval:%d", retval);
clixon_debug(CLIXON_DBG_PROC, "retval:%d", retval);
return retval;
}

Expand All @@ -902,12 +907,12 @@ clixon_process_sched(int fd,
int isrunning; /* Process is actually running */
int sched = 0;

clixon_debug(CLIXON_DBG_DEFAULT, "");
clixon_debug(CLIXON_DBG_PROC, "");
if (_proc_entry_list == NULL)
goto ok;
pe = _proc_entry_list;
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));
/* Execute pending operations and not already exiting */
if (pe->pe_operation != PROC_OP_NONE){
Expand Down Expand Up @@ -942,7 +947,7 @@ clixon_process_sched(int fd,
pe->pe_uid, pe->pe_gid, pe->pe_fdkeep,
&pe->pe_pid) < 0)
goto done;
clixon_debug(CLIXON_DBG_DEFAULT,
clixon_debug(CLIXON_DBG_PROC | CLIXON_DBG_DETAIL,
"%s(%d) %s --%s--> %s",
pe->pe_name, pe->pe_pid,
clicon_int2str(proc_state_map, pe->pe_state),
Expand Down Expand Up @@ -970,7 +975,7 @@ clixon_process_sched(int fd,
pe->pe_uid, pe->pe_gid, pe->pe_fdkeep,
&pe->pe_pid) < 0)
goto done;
clixon_debug(CLIXON_DBG_DEFAULT,
clixon_debug(CLIXON_DBG_PROC | CLIXON_DBG_DETAIL,
"%s(%d) %s --%s--> %s",
pe->pe_name, pe->pe_pid,
clicon_int2str(proc_state_map, pe->pe_state),
Expand All @@ -994,7 +999,7 @@ clixon_process_sched(int fd,
ok:
retval = 0;
done:
clixon_debug(CLIXON_DBG_DEFAULT, "retval:%d", retval);
clixon_debug(CLIXON_DBG_PROC, "retval:%d", retval);
return retval;
}

Expand All @@ -1016,15 +1021,15 @@ clixon_process_sched_register(clixon_handle h,
struct timeval t;
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);
if (delay)
timeradd(&t, &t1, &t);
if (clixon_event_reg_timeout(t, clixon_process_sched, h, "process") < 0)
goto done;
retval = 0;
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;
}

Expand All @@ -1045,28 +1050,28 @@ clixon_process_waitpid(clixon_handle h)
int status = 0;
pid_t wpid;

clixon_debug(CLIXON_DBG_DEFAULT, "");
clixon_debug(CLIXON_DBG_PROC, "");
if (_proc_entry_list == NULL)
goto ok;
if ((pe = _proc_entry_list) != NULL)
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,
clicon_int2str(proc_state_map, pe->pe_state),
clicon_int2str(proc_operation_map, pe->pe_operation));
if (pe->pe_pid != 0
&& (pe->pe_state == PROC_STATE_RUNNING || pe->pe_state == PROC_STATE_EXITING)
// && (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);
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;
switch (pe->pe_operation){
case PROC_OP_NONE: /* Spontaneous / External termination */
case PROC_OP_STOP:
clixon_debug(CLIXON_DBG_DEFAULT,
clixon_debug(CLIXON_DBG_PROC | CLIXON_DBG_DETAIL,
"%s(%d) %s --%s--> %s",
pe->pe_name, pe->pe_pid,
clicon_int2str(proc_state_map, pe->pe_state),
Expand All @@ -1085,7 +1090,7 @@ clixon_process_waitpid(clixon_handle h)
&pe->pe_pid) < 0)
goto done;
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,
clicon_int2str(proc_state_map, pe->pe_state),
clicon_int2str(proc_operation_map, pe->pe_operation),
Expand All @@ -1101,15 +1106,15 @@ clixon_process_waitpid(clixon_handle h)
break; /* pid is unique */
}
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 = NEXTQ(process_entry_t *, pe);
} while (pe && pe != _proc_entry_list);
ok:
retval = 0;
done:
clixon_debug(CLIXON_DBG_DEFAULT, "retval:%d", retval);
clixon_debug(CLIXON_DBG_PROC, "retval:%d", retval);
return retval;
}

Expand Down

0 comments on commit af55bf1

Please sign in to comment.