Add logstr to logd.on_log callback

.gitignore

@@ -58,3 +58,6 @@ src/logdconfig.lua
 src/logdconfig.lua.h
 
 test/helper.sh
+
+# six
+*.swp

README.md

@@ -16,9 +16,9 @@ Logd is a log scanner daemon that exposes a Lua API to run arbitrary logic on st
 
 | Hook | Description |
 | --- | --- |
-| `function logd.on_log (logptr)` | Logs are scanned and supplied to this handler. Use `logd.log_*` set of functions to manipulate them. |
+| `function logd.on_log (logptr, logstr)` | Logs are scanned and supplied to this handler. Use `logd.log_*` set of functions to manipulate them. |
 | `function logd.on_exit (code, reason)` | Called when collector is gracefully terminating. |
-| `function logd.on_error (error, logptr, at)` | Called when collector failed to scan a log line. Scanning will resume after this function returns. |
+| `function logd.on_error (error, logptr, at, logstr)` | Called when collector failed to scan a log line. Scanning will resume after this function returns. |
 
 ## Preloaded Lua modules
 - [logd](#logd-module-api)

src/logd.c

@@ -145,8 +145,7 @@ char* args_init(int argc, char* argv[])
 				return NULL;
 			}
 			backoff =
-			  strncmp(LINEAL_BACKOFF, optarg, strlen(LINEAL_BACKOFF)) == 0 ? 1 :
-																			 2;
+			  strncmp(LINEAL_BACKOFF, optarg, strlen(LINEAL_BACKOFF)) == 0 ? 1 : 2;
 			break;
 		case 'd':
 			if ((args.reopen_delay = parse_non_negative_int(optarg)) == -1 ||
@@ -465,16 +464,16 @@ bool logd_buf_compact()
 	return 1;
 }
 
-void call_on_error(lua_t* l, const char* err, log_t* partial, const char* at)
+void call_on_error(lua_t* l, const char* err, log_t* partial, const char* data, const char* at)
 {
 	partial->is_safe = true;
-	lua_call_on_error(lstate, err, partial, at);
+	lua_call_on_error(lstate, err, partial, data, at);
 	partial->is_safe = false;
 }
 
-#define CALL_ON_LOG(lstate, res)                                               \
+#define CALL_ON_LOG(lstate, input, res)                                        \
 	res.log->is_safe = true;                                                   \
-	lua_call_on_log(lstate, res.log);                                          \
+	lua_call_on_log(lstate, input, res.log);                                   \
 	buf_consume(b, res.consumed);                                              \
 	logd_reset_scanner();                                                      \
 	res.log->is_safe = false;
@@ -504,14 +503,14 @@ void on_read_eof()
 	res = scan_scanner(scanner, b->next_read, buf_readable(b));
 	switch (res.type) {
 	case SCAN_COMPLETE:
-		CALL_ON_LOG(lstate, res);
+		CALL_ON_LOG(lstate, b->next_read, res);
 		goto scan;
 	case SCAN_ERROR:
 		DEBUG_LOG("EOF scan error: %s", res.error.msg);
-		buf_ack(b, res.consumed);
 		if (lua_on_error_defined(lstate)) {
-			call_on_error(lstate, res.error.msg, res.log, res.error.at);
+			call_on_error(lstate, res.error.msg, res.log, b->next_read, res.error.at);
 		}
+		buf_ack(b, res.consumed);
 		logd_reset_scanner();
 		goto scan;
 	case SCAN_PARTIAL:
@@ -564,7 +563,7 @@ void on_read_skip(uv_poll_t* req, int status, int events)
 		call_on_error(lstate,
 		  "log line was skipped because it is more than " STR(
 			LOGD_BUF_MAX_CAP) " bytes",
-		  res.log, "");
+		  res.log, b->next_read, "");
 	}
 	buf_ack(b, res.consumed);
 	DEBUG_LOG("successfully skipped line: buffer has now %zu readable bytes "
@@ -593,15 +592,15 @@ void on_read(uv_poll_t* req, int status, int events)
 
 	case SCAN_COMPLETE:
 		// DEBUG_LOG("scanned new log: %p", &res.log);
-		CALL_ON_LOG(lstate, res);
+		CALL_ON_LOG(lstate, b->next_read, res);
 		goto scan;
 
 	case SCAN_ERROR:
 		DEBUG_LOG("scan error: %s", res.error.msg);
-		buf_ack(b, res.consumed);
 		if (lua_on_error_defined(lstate)) {
-			call_on_error(lstate, res.error.msg, res.log, res.error.at);
+			call_on_error(lstate, res.error.msg, res.log, b->next_read, res.error.at);
 		}
+		buf_ack(b, res.consumed);
 		logd_reset_scanner();
 		goto scan;
 

src/lua.c

@@ -225,14 +225,15 @@ int lua_init(lua_t* l, uv_loop_t* loop, const char* script)
 	return -1;
 }
 
-void lua_call_on_log(lua_t* l, log_t* log)
+void lua_call_on_log(lua_t* l, const char* data, log_t* log)
 {
 	lua_getglobal(l->state, ON_LOG_INTERNAL);
 	DEBUG_ASSERT(lua_isfunction(l->state, -1));
 
 	lua_pushlightuserdata(l->state, log);
+	lua_pushstring(l->state, data);
 
-	lua_call(l->state, 1, 0);
+	lua_call(l->state, 2, 0);
 }
 
 bool lua_on_error_defined(lua_t* l)
@@ -247,16 +248,17 @@ bool lua_on_error_defined(lua_t* l)
 }
 
 void lua_call_on_error(
-  lua_t* l, const char* err, log_t* partial, const char* at)
+  lua_t* l, const char* err, log_t* partial, const char* data, const char* at)
 {
 	lua_push_on_error(l->state);
 	DEBUG_ASSERT(lua_isfunction(l->state, -1));
 
 	lua_pushstring(l->state, err);
 	lua_pushlightuserdata(l->state, partial);
 	lua_pushstring(l->state, at);
+	lua_pushstring(l->state, data);
 
-	lua_call(l->state, 3, 0);
+	lua_call(l->state, 4, 0);
 	lua_pop(l->state, 1); // logd module
 }
 

src/lua.h

@@ -15,10 +15,10 @@ typedef struct lua_s {
 
 lua_t* lua_create(uv_loop_t* loop, const char* script);
 int lua_init(lua_t* l, uv_loop_t* loop, const char* script);
-void lua_call_on_log(lua_t*, log_t* log);
+void lua_call_on_log(lua_t*, const char* data, log_t* log);
 bool lua_on_error_defined(lua_t*);
 void lua_call_on_error(
-  lua_t*, const char* err, log_t* partial, const char* remaining);
+  lua_t*, const char* err, log_t* partial, const char* data, const char* remaining);
 bool lua_on_exit_defined(lua_t*);
 void lua_call_on_exit(
   lua_t* l, enum exit_reason reason, const char* reason_str);

test/test_error.sh

@@ -39,26 +39,31 @@ end
 function logd.on_exit()
 	assert(logs == 3)
 end
-function logd.on_error(error, logptr, at)
+function logd.on_error(error, logptr, at, logstr)
 	local error_expected
 	local at_expected
+	local logstr_expected
 	errors = errors + 1
 	-- should be able to use log_get on logptr
 	logd.log_get(logptr, "date")
 	if errors == 1 then
 		error_expected = "incomplete header"
 		at_expected = ""
+		logstr_expected = ""
 	elseif errors == 2 then
 		error_expected = "invalid date or time in log header"
 		at_expected = "GARBAGE DEBUG	[thread4]	clazz	callType: b: ,"
+		logstr_expected = "2018-05-12 GARBAGE DEBUG	[thread4]	clazz	callType: b: ,"
 	else
 		error_expected = "reached max number of log properties: $LOGD_SLAB_CAP"
+		logstr_expected = "2018-05-12 12:55:22 TRACE	[thread5]	clazz	tooManyProps: b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, : c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C, b: c: C,"
 	end
 
 	assert(errors < 4)
 	assert(error == error_expected, string.format("error was '%s' instead of '%s'", error, error_expected))
 	if at_expected ~= nil then
 		assert(at == at_expected, string.format("at was '%s' instead of '%s'", at, at_expected))
+		assert(logstr == logstr_expected, string.format("logstr was '%s' instead of '%s'", logstr, logstr_expected))
 	end
 end
 EOF

test/test_log.sh

@@ -31,38 +31,43 @@ EOF
 cat >$SCRIPT << EOF
 local logd = require("logd")
 local counter = 0
-function logd.on_log(logptr)
+function logd.on_log(logptr, logstr)
 	if counter == 0 then
 		assert("ERROR" == logd.log_get(logptr, "level"))
 		assert("thread1" == logd.log_get(logptr, "thread"))
 		assert("clazz" == logd.log_get(logptr, "class"))
 		assert(nil == logd.log_get(logptr, "callType"))
 		assert("A" == logd.log_get(logptr, "a"))
+		assert("2018-05-12 12:51:28 ERROR	[thread1]	clazz	a: A, ", logstr)
 	elseif counter == 1 then
 		assert("WARN" == logd.log_get(logptr, "level"))
 		assert("thread2" == logd.log_get(logptr, "thread"))
 		assert("clazz" == logd.log_get(logptr, "class"))
 		assert("callType" == logd.log_get(logptr, "callType"))
 		assert("B" == logd.log_get(logptr, "b"))
+		assert("2018-05-12 12:52:22 WARN	[thread2]	clazz	callType: b: B", logstr)
 	elseif counter == 2 then
 		assert("INFO" == logd.log_get(logptr, "level"))
 		assert("thread3" == logd.log_get(logptr, "thread"))
 		assert("clazz" == logd.log_get(logptr, "class"))
 		assert("callType" == logd.log_get(logptr, "callType"))
 		assert("C" == logd.log_get(logptr, "c"))
+		assert("2018-05-12 12:53:22 INFO	[thread3]	clazz	callType: c: C, ", logstr)
 	elseif counter == 3 then
 		assert("DEBUG" == logd.log_get(logptr, "level"))
 		assert("thread4" == logd.log_get(logptr, "thread"))
 		assert("clazz" == logd.log_get(logptr, "class"))
 		assert("callType" == logd.log_get(logptr, "callType"))
 		assert("" == logd.log_get(logptr, "b"))
+		assert("2018-05-12 12:54:22 DEBUG	[thread4]	clazz	callType: b: ,", logstr)
 	else
 		assert("TRACE" == logd.log_get(logptr, "level"))
 		assert("thread5" == logd.log_get(logptr, "thread"))
 		assert("clazz" == logd.log_get(logptr, "class"))
 		assert("callType" == logd.log_get(logptr, "callType"))
 		assert("c: C" == logd.log_get(logptr, "b"))
 		assert(nil == logd.log_get(logptr, "c"))
+		assert("2018-05-12 12:55:22 TRACE	[thread5]	clazz	callType: b: c: C, ", logstr)
 	end
 	counter = counter + 1
 end