From 07d4e9512a1b299ebad7eff66fd77d16daf058f8 Mon Sep 17 00:00:00 2001 From: kanoi Date: Sun, 20 Sep 2015 01:24:32 +1000 Subject: [PATCH] ckdb/php - separate logging of ckpool msgs vs other, add a web timestamp --- pool/db.php | 6 +++-- src/ckdb.c | 69 ++++++++++++++++++++++++++++---------------------- src/ckdb.h | 16 +++++++++--- src/ckdb_cmd.c | 25 +++++++----------- 4 files changed, 64 insertions(+), 52 deletions(-) diff --git a/pool/db.php b/pool/db.php index a72591be..2b9d4c5e 100644 --- a/pool/db.php +++ b/pool/db.php @@ -139,13 +139,15 @@ function msgEncode($cmd, $id, $fields, $user) { global $send_sep, $fld_sep, $val_sep; - $t = time() % 10000; + $now = time(); + $t = $now % 10000; $msg = $cmd . $send_sep . $id.$t . $send_sep; foreach ($fields as $name => $value) $msg .= $name . $val_sep . $value . $fld_sep; $msg .= 'createcode' . $val_sep . 'php' . $fld_sep; $msg .= 'createby' . $val_sep . $user . $fld_sep; - $msg .= 'createinet' . $val_sep . zeip(); + $msg .= 'createinet' . $val_sep . zeip(). $fld_sep; + $msg .= 'webtime' . $val_sep . $now; adm($user, $msg); return $msg; } diff --git a/src/ckdb.c b/src/ckdb.c index 154916f5..6e4e03a7 100644 --- a/src/ckdb.c +++ b/src/ckdb.c @@ -497,17 +497,18 @@ K_TREE *userinfo_root; K_LIST *userinfo_free; K_STORE *userinfo_store; -static char logname[512]; +static char logname_db[512]; +static char logname_io[512]; static char *dbcode; // low spec version of rotating_log() - no locking -static bool rotating_log_nolock(char *msg) +static bool rotating_log_nolock(char *msg, char *prefix) { char *filename; FILE *fp; bool ok = false; - filename = rotating_filename(logname, time(NULL)); + filename = rotating_filename(prefix, time(NULL)); fp = fopen(filename, "a+e"); if (unlikely(!fp)) { LOGERR("Failed to fopen %s in rotating_log!", filename); @@ -523,7 +524,7 @@ stageleft: return ok; } -static void log_queue_message(char *msg) +static void log_queue_message(char *msg, bool db) { K_ITEM *lq_item; LOGQUEUE *lq; @@ -534,6 +535,7 @@ static void log_queue_message(char *msg) lq->msg = strdup(msg); if (!(lq->msg)) quithere(1, "malloc (%d) OOM", (int)strlen(msg)); + lq->db = db; k_add_tail(logqueue_store, lq_item); K_WUNLOCK(logqueue_free); } @@ -2518,12 +2520,18 @@ static enum cmd_values breakdown(K_ITEM **ml_item, char *buf, tv_t *now, } if (ckdb_cmds[msgline->which_cmds].cmd_val == CMD_END) { + LOGQUE(buf, false); LOGERR("Listener received unknown command: '%.42s...", st2 = safe_text(buf)); FREENULL(st2); goto nogood; } + if (ckdb_cmds[msgline->which_cmds].access & ACCESS_POOL) + LOGQUE(buf, true); + else + LOGQUE(buf, false); + if (noid) { if (ckdb_cmds[msgline->which_cmds].noid) { free(cmdptr); @@ -3614,7 +3622,8 @@ static void *logger(__maybe_unused void *arg) setnow(&now); snprintf(buf, sizeof(buf), "logstart.%ld,%ld", now.tv_sec, now.tv_usec); - LOGFILE(buf); + LOGFILE(buf, logname_db); + LOGFILE(buf, logname_io); while (!everyone_die) { K_WLOCK(logqueue_free); @@ -3622,7 +3631,10 @@ static void *logger(__maybe_unused void *arg) K_WUNLOCK(logqueue_free); while (lq_item) { DATA_LOGQUEUE(lq, lq_item); - LOGFILE(lq->msg); + if (lq->db) + LOGFILE(lq->msg, logname_db); + else + LOGFILE(lq->msg, logname_io); FREENULL(lq->msg); K_WLOCK(logqueue_free); @@ -3641,14 +3653,18 @@ static void *logger(__maybe_unused void *arg) setnow(&now); snprintf(buf, sizeof(buf), "logstopping.%d.%ld,%ld", count, now.tv_sec, now.tv_usec); - LOGFILE(buf); + LOGFILE(buf, logname_db); + LOGFILE(buf, logname_io); if (count) LOGERR("%s", buf); lq_item = logqueue_store->head; copy_tv(&then, &now); while (lq_item) { DATA_LOGQUEUE(lq, lq_item); - LOGFILE(lq->msg); + if (lq->db) + LOGFILE(lq->msg, logname_db); + else + LOGFILE(lq->msg, logname_io); FREENULL(lq->msg); count--; setnow(&now); @@ -3666,7 +3682,8 @@ static void *logger(__maybe_unused void *arg) setnow(&now); snprintf(buf, sizeof(buf), "logstop.%ld,%ld", now.tv_sec, now.tv_usec); - LOGFILE(buf); + LOGFILE(buf, logname_db); + LOGFILE(buf, logname_io); LOGWARNING("%s", buf); return NULL; @@ -3687,8 +3704,7 @@ static void *socketer(__maybe_unused void *arg) proc_instance_t *pi = (proc_instance_t *)arg; unixsock_t *us = &pi->us; char *end, *ans = NULL, *rep = NULL, *buf = NULL, *dot; - char *last_auth = NULL, *reply_auth = NULL; - char *last_addrauth = NULL, *reply_addrauth = NULL; + // No dup check for pool stats, the SEQ code will handle that char *last_chkpass = NULL, *reply_chkpass = NULL; char *last_adduser = NULL, *reply_adduser = NULL; char *last_newpass = NULL, *reply_newpass = NULL; @@ -3768,10 +3784,7 @@ static void *socketer(__maybe_unused void *arg) dup = false; show_dup = true; // These are ordered approximately most likely first - if (last_auth && strcmp(last_auth, buf) == 0) { - reply_last = reply_auth; - dup = true; - } else if (last_chkpass && strcmp(last_chkpass, buf) == 0) { + if (last_chkpass && strcmp(last_chkpass, buf) == 0) { reply_last = reply_chkpass; dup = true; } else if (last_adduser && strcmp(last_adduser, buf) == 0) { @@ -3783,9 +3796,6 @@ static void *socketer(__maybe_unused void *arg) } else if (last_newid && strcmp(last_newid, buf) == 0) { reply_last = reply_newid; dup = true; - } else if (last_addrauth && strcmp(last_addrauth, buf) == 0) { - reply_last = reply_addrauth; - dup = true; } else if (last_userset && strcmp(last_userset, buf) == 0) { reply_last = reply_userset; dup = true; @@ -3814,7 +3824,8 @@ static void *socketer(__maybe_unused void *arg) *dot = '\0'; snprintf(reply, sizeof(reply), "%s%ld,%ld.%s", LOGDUP, now.tv_sec, now.tv_usec, duptype); - LOGQUE(reply); + // dup cant be pool + LOGQUE(reply, false); if (show_dup) LOGWARNING("Duplicate '%s' message received", duptype); else @@ -3823,7 +3834,6 @@ static void *socketer(__maybe_unused void *arg) int seqentryflags = SE_SOCKET; if (!reload_queue_complete) seqentryflags = SE_EARLYSOCK; - LOGQUE(buf); cmdnum = breakdown(&ml_item, buf, &now, seqentryflags); DATA_MSGLINE(msgline, ml_item); replied = false; @@ -3956,12 +3966,6 @@ static void *socketer(__maybe_unused void *arg) send_unix_msg(sockd, rep); FREENULL(ans); switch (cmdnum) { - case CMD_AUTH: - STORELASTREPLY(auth); - break; - case CMD_ADDRAUTH: - STORELASTREPLY(addrauth); - break; case CMD_CHKPASS: STORELASTREPLY(chkpass); break; @@ -4233,7 +4237,6 @@ static void reload_line(PGconn *conn, char *filename, uint64_t count, char *buf) __func__, count); } - LOGQUE(buf); // ml_item is set for all but CMD_REPLY cmdnum = breakdown(&ml_item, buf, &now, SE_RELOAD); DATA_MSGLINE(msgline, ml_item); @@ -4444,7 +4447,8 @@ static bool reload_from(tv_t *start) copy_tv(&begin, &now); tvs_to_buf(&now, run, sizeof(run)); snprintf(reload_buf, MAX_READ, "reload.%s.s0", run); - LOGQUE(reload_buf); + LOGQUE(reload_buf, true); + LOGQUE(reload_buf, false); conn = dbconnect(); @@ -4537,7 +4541,8 @@ static bool reload_from(tv_t *start) diff = 1; snprintf(reload_buf, MAX_READ, "reload.%s.%"PRIu64, run, total); - LOGQUE(reload_buf); + LOGQUE(reload_buf, true); + LOGQUE(reload_buf, false); LOGWARNING("%s(): read %d file%s, total %"PRIu64" line%s %.2f/s", __func__, processing, processing == 1 ? "" : "s", @@ -5582,7 +5587,11 @@ int main(int argc, char **argv) quit(1, "Failed to open log file %s", buf); ckp.logfd = fileno(ckp.logfp); - snprintf(logname, sizeof(logname), "%s%s-db%s-", + // -db is ckpool messages + snprintf(logname_db, sizeof(logname_db), "%s%s-db%s-", + ckp.logdir, ckp.name, dbcode); + // -io is everything else + snprintf(logname_io, sizeof(logname_io), "%s%s-io%s-", ckp.logdir, ckp.name, dbcode); setnow(&now); diff --git a/src/ckdb.h b/src/ckdb.h index a0963ae9..85930c7b 100644 --- a/src/ckdb.h +++ b/src/ckdb.h @@ -55,7 +55,7 @@ #define DB_VLOCK "1" #define DB_VERSION "1.0.2" -#define CKDB_VERSION DB_VERSION"-1.303" +#define CKDB_VERSION DB_VERSION"-1.310" #define WHERE_FFL " - from %s %s() line %d" #define WHERE_FFL_HERE __FILE__, __func__, __LINE__ @@ -438,8 +438,8 @@ enum cmd_values { // CCLs are every ... #define ROLL_S 3600 -#define LOGQUE(_msg) log_queue_message(_msg) -#define LOGFILE(_msg) rotating_log_nolock(_msg) +#define LOGQUE(_msg, _db) log_queue_message(_msg, _db) +#define LOGFILE(_msg, _prefix) rotating_log_nolock(_msg, _prefix) #define LOGDUP "dup." // *** @@ -711,6 +711,7 @@ enum cmd_values { // LOGQUEUE typedef struct logqueue { char *msg; + bool db; } LOGQUEUE; #define ALLOC_LOGQUEUE 1024 @@ -2608,6 +2609,13 @@ extern bool check_db_version(PGconn *conn); // *** ckdb_cmd.c // *** +// TODO: limit access by having seperate sockets for each +#define ACCESS_POOL (1 << 0) +#define ACCESS_SYSTEM (1 << 1) +#define ACCESS_WEB (1 << 2) +#define ACCESS_PROXY (1 << 3) +#define ACCESS_CKDB (1 << 4) + struct CMDS { enum cmd_values cmd_val; char *cmd_str; @@ -2616,7 +2624,7 @@ struct CMDS { char *(*func)(PGconn *, char *, char *, tv_t *, char *, char *, char *, tv_t *, K_TREE *); enum seq_num seq; - char *access; + int access; }; extern struct CMDS ckdb_cmds[]; diff --git a/src/ckdb_cmd.c b/src/ckdb_cmd.c index 1f501c2d..45ac8393 100644 --- a/src/ckdb_cmd.c +++ b/src/ckdb_cmd.c @@ -6413,13 +6413,6 @@ static char *cmd_btcset(__maybe_unused PGconn *conn, char *cmd, char *id, return strdup(buf); } -// TODO: limit access by having seperate sockets for each -#define ACCESS_POOL "p" -#define ACCESS_SYSTEM "s" -#define ACCESS_WEB "w" -#define ACCESS_PROXY "x" -#define ACCESS_CKDB "c" - /* The socket command format is as follows: * Basic structure: * cmd.ID.fld1=value1 FLDSEP fld2=value2 FLDSEP fld3=... @@ -6482,8 +6475,8 @@ static char *cmd_btcset(__maybe_unused PGconn *conn, char *cmd, char *id, // cmd_val cmd_str noid createdate func seq access struct CMDS ckdb_cmds[] = { { CMD_TERMINATE, "terminate", true, false, NULL, SEQ_NONE, ACCESS_SYSTEM }, - { CMD_PING, "ping", true, false, NULL, SEQ_NONE, ACCESS_SYSTEM ACCESS_POOL ACCESS_WEB }, - { CMD_VERSION, "version", true, false, NULL, SEQ_NONE, ACCESS_SYSTEM ACCESS_POOL ACCESS_WEB }, + { CMD_PING, "ping", true, false, NULL, SEQ_NONE, ACCESS_SYSTEM | ACCESS_WEB }, + { CMD_VERSION, "version", true, false, NULL, SEQ_NONE, ACCESS_SYSTEM | ACCESS_WEB }, { CMD_LOGLEVEL, "loglevel", true, false, NULL, SEQ_NONE, ACCESS_SYSTEM }, { CMD_FLUSH, "flush", true, false, NULL, SEQ_NONE, ACCESS_SYSTEM }, { CMD_SHARELOG, STR_WORKINFO, false, true, cmd_sharelog, SEQ_WORKINFO, ACCESS_POOL }, @@ -6516,15 +6509,15 @@ struct CMDS ckdb_cmds[] = { { CMD_GETOPTS, "getopts", false, false, cmd_getopts, SEQ_NONE, ACCESS_WEB }, { CMD_SETOPTS, "setopts", false, false, cmd_setopts, SEQ_NONE, ACCESS_WEB }, { CMD_DSP, "dsp", false, false, cmd_dsp, SEQ_NONE, ACCESS_SYSTEM }, - { CMD_STATS, "stats", true, false, cmd_stats, SEQ_NONE, ACCESS_SYSTEM ACCESS_WEB }, - { CMD_PPLNS, "pplns", false, false, cmd_pplns, SEQ_NONE, ACCESS_SYSTEM ACCESS_WEB }, - { CMD_PPLNS2, "pplns2", false, false, cmd_pplns2, SEQ_NONE, ACCESS_SYSTEM ACCESS_WEB }, + { CMD_STATS, "stats", true, false, cmd_stats, SEQ_NONE, ACCESS_SYSTEM | ACCESS_WEB }, + { CMD_PPLNS, "pplns", false, false, cmd_pplns, SEQ_NONE, ACCESS_SYSTEM | ACCESS_WEB }, + { CMD_PPLNS2, "pplns2", false, false, cmd_pplns2, SEQ_NONE, ACCESS_SYSTEM | ACCESS_WEB }, { CMD_PAYOUTS, "payouts", false, false, cmd_payouts, SEQ_NONE, ACCESS_SYSTEM }, - { CMD_MPAYOUTS, "mpayouts", false, false, cmd_mpayouts, SEQ_NONE, ACCESS_SYSTEM ACCESS_WEB }, - { CMD_SHIFTS, "shifts", false, false, cmd_shifts, SEQ_NONE, ACCESS_SYSTEM ACCESS_WEB }, - { CMD_USERSTATUS,"userstatus", false, false, cmd_userstatus, SEQ_NONE, ACCESS_SYSTEM ACCESS_WEB }, + { CMD_MPAYOUTS, "mpayouts", false, false, cmd_mpayouts, SEQ_NONE, ACCESS_SYSTEM | ACCESS_WEB }, + { CMD_SHIFTS, "shifts", false, false, cmd_shifts, SEQ_NONE, ACCESS_SYSTEM | ACCESS_WEB }, + { CMD_USERSTATUS,"userstatus", false, false, cmd_userstatus, SEQ_NONE, ACCESS_SYSTEM | ACCESS_WEB }, { CMD_MARKS, "marks", false, false, cmd_marks, SEQ_NONE, ACCESS_SYSTEM }, - { CMD_PSHIFT, "pshift", false, false, cmd_pshift, SEQ_NONE, ACCESS_SYSTEM ACCESS_WEB }, + { CMD_PSHIFT, "pshift", false, false, cmd_pshift, SEQ_NONE, ACCESS_SYSTEM | ACCESS_WEB }, { CMD_SHSTA, "shsta", true, false, cmd_shsta, SEQ_NONE, ACCESS_SYSTEM }, { CMD_USERINFO, "userinfo", false, false, cmd_userinfo, SEQ_NONE, ACCESS_WEB }, { CMD_BTCSET, "btcset", false, false, cmd_btcset, SEQ_NONE, ACCESS_SYSTEM },