Include extra details when storing unparsable and uninsertable lines.

Now includes the hostnameId, timestamp and optionally error message.
Updates idx_entities_retryinsert to account for details not being NULL.
Also fixes the issue where the entities inserted and rollback would
still be recorded in the entity cache if the access log insert failed.
This would have lead to PK violations later on.

10 files changed, 130 insertions, 50 deletions

diff --git a/src/ingestor.cpp b/src/ingestor.cpp
index ff5cd92..077f7d8 100644
--- a/src/ingestor.cpp
+++ b/src/ingestor.cpp
@@ -420,17 +420,16 @@ namespace WebStat {
 				try {
 					DB::TransactionScope lineTx {*dbconn};
 					storeNewEntities(dbconn, valuesEntities);
-					existingEntities()->insert_range(valuesEntities | ENTITY_IDS);
 					storeLogLine(dbconn, values);
+					existingEntities()->insert_range(valuesEntities | ENTITY_IDS);
 				}
 				catch (const DB::Error & originalError) {
 					try {
 						DB::TransactionScope lineTx {*dbconn};
-						auto uninsertableLine = ToEntity<EntityType::UninsertableLine> {}(line);
-						storeNewEntity(dbconn, uninsertableLine);
+						const auto uninsertableLineId = storeUninsertableLine(dbconn, line, originalError);
 						log(LOG_NOTICE,
 								"Failed to store parsed line and/or associated entties, but did store raw line, %u:%s",
-								*uninsertableLine.id, line.c_str());
+								uninsertableLineId, line.c_str());
 					}
 					catch (const std::exception & excp) {
 						log(LOG_NOTICE, "Failed to store line in any form, DB connection lost? %s", excp.what());
@@ -440,9 +439,8 @@ namespace WebStat {
 			}
 			else {
 				stats.linesParseFailed++;
-				auto unparsableLine = ToEntity<EntityType::UnparsableLine> {}(line);
-				storeNewEntity(dbconn, unparsableLine);
-				log(LOG_NOTICE, "Failed to parse line, this is a bug: %u:%s", *unparsableLine.id, line.c_str());
+				const auto unparsableLineId = storeUnparsableLine(dbconn, line);
+				log(LOG_NOTICE, "Failed to parse line, this is a bug: %u:%s", unparsableLineId, line.c_str());
 			}
 		}
 	}
@@ -652,6 +650,20 @@ namespace WebStat {
 		stats.entitiesInserted += 1;
 	}
 
+	EntityId
+	Ingestor::storeUnparsableLine(DB::Connection * dbconn, const std::string_view line) const
+	{
+		return insert<EntityId>(dbconn, SQL::UNPARSABLE_INSERT, SQL::UNPARSABLE_INSERT_OPTS, line, hostnameId);
+	}
+
+	EntityId
+	Ingestor::storeUninsertableLine(
+			DB::Connection * dbconn, const std::string_view line, const std::exception & excp) const
+	{
+		return insert<EntityId>(
+				dbconn, SQL::UNINSERTABLE_INSERT, SQL::UNINSERTABLE_INSERT_OPTS, line, hostnameId, excp.what());
+	}
+
 	void
 	Ingestor::onNewUserAgent(const Entity & entity) const
 	{
diff --git a/src/ingestor.hpp b/src/ingestor.hpp
index ce4ac09..dacfdf7 100644
--- a/src/ingestor.hpp
+++ b/src/ingestor.hpp
@@ -117,6 +117,8 @@ namespace WebStat {
 		void fillKnownEntities(std::span<Entity *>) const;
 		void storeNewEntities(DB::Connection *, std::span<Entity *>) const;
 		void storeNewEntity(DB::Connection *, Entity &) const;
+		EntityId storeUnparsableLine(DB::Connection *, std::string_view) const;
+		EntityId storeUninsertableLine(DB::Connection *, std::string_view, const std::exception &) const;
 		void onNewUserAgent(const Entity &) const;
 		auto withCurlLock(auto &&...);
 		bool haveCurlOperations();
diff --git a/src/schema.sql b/src/schema.sql
index a4ea0e8..40cab51 100644
--- a/src/schema.sql
+++ b/src/schema.sql
@@ -92,7 +92,7 @@ CREATE UNIQUE INDEX uni_entities_value ON entities(MD5(value), type);
 
 CREATE INDEX idx_entities_retryinsert ON bad_lines(id)
 WHERE
-	type = 'uninsertable_line' AND detail IS NULL;
+	type = 'uninsertable_line' AND detail ->> 'retriedAt' IS NULL;
 
 CREATE OR REPLACE FUNCTION entity(newValue text, newType entity)
 	RETURNS TABLE(
diff --git a/src/sql.cpp b/src/sql.cpp
index 63e946c..2b91aab 100644
--- a/src/sql.cpp
+++ b/src/sql.cpp
@@ -16,6 +16,12 @@ namespace WebStat::SQL {
 	const std::string ENTITY_INSERT {
 #embed "sql/entityInsert.sql"
 	};
+	const std::string UNPARSABLE_INSERT {
+#embed "sql/unparsableInsert.sql"
+	};
+	const std::string UNINSERTABLE_INSERT {
+#embed "sql/uninsertableInsert.sql"
+	};
 	const std::string ENTITY_UPDATE_DETAIL {
 #embed "sql/entityUpdateDetail.sql"
 	};
@@ -40,6 +46,8 @@ namespace WebStat::SQL {
 	HASH_OPTS(ACCESS_LOG_INSERT);
 	HASH_OPTS(ACCESS_LOG_PURGE_OLD);
 	HASH_OPTS(ENTITY_INSERT);
+	HASH_OPTS(UNPARSABLE_INSERT);
+	HASH_OPTS(UNINSERTABLE_INSERT);
 	HASH_OPTS(ENTITY_UPDATE_DETAIL);
 	HASH_OPTS(HOST_UPSERT);
 	const DB::CommandOptionsPtr SELECT_UNINSERTABLE_OPTS
diff --git a/src/sql.hpp b/src/sql.hpp
index ae3559a..346754c 100644
--- a/src/sql.hpp
+++ b/src/sql.hpp
@@ -12,6 +12,8 @@ namespace WebStat::SQL {
 	EMBED_DECLARE(ACCESS_LOG_PURGE_OLD);
 	EMBED_DECLARE(ENTITY_INSERT);
 	EMBED_DECLARE(ENTITY_UPDATE_DETAIL);
+	EMBED_DECLARE(UNPARSABLE_INSERT);
+	EMBED_DECLARE(UNINSERTABLE_INSERT);
 	EMBED_DECLARE(HOST_UPSERT);
 	EMBED_DECLARE(SELECT_UNINSERTABLE);
 	EMBED_DECLARE(DELETE_ENTITY);
diff --git a/src/sql/markEntityRetried.sql b/src/sql/markEntityRetried.sql
index 6ec2263..a52a15c 100644
--- a/src/sql/markEntityRetried.sql
+++ b/src/sql/markEntityRetried.sql
@@ -1,6 +1,6 @@
 UPDATE
 	entities
 SET
-	detail = jsonb_build_object('retriedAt', CURRENT_TIMESTAMP at time zone 'utc', 'error', ?::text)
+	detail = detail || jsonb_build_object('retriedAt', CURRENT_TIMESTAMP at time zone 'utc', 'error', ?::text)
 WHERE
 	id = ?
diff --git a/src/sql/selectUninsertableLines.sql b/src/sql/selectUninsertableLines.sql
index 894ab67..060e800 100644
--- a/src/sql/selectUninsertableLines.sql
+++ b/src/sql/selectUninsertableLines.sql
@@ -5,7 +5,7 @@ FROM
 	entities
 WHERE
 	type = 'uninsertable_line'
-	AND detail IS NULL
+	AND detail ->> 'retriedAt' IS NULL
 ORDER BY
 	id
 LIMIT ?
diff --git a/src/sql/uninsertableInsert.sql b/src/sql/uninsertableInsert.sql
new file mode 100644
index 0000000..5b09393
--- /dev/null
+++ b/src/sql/uninsertableInsert.sql
@@ -0,0 +1,5 @@
+INSERT INTO entities(type, value, detail)
+	VALUES ('uninsertable_line', $1, jsonb_build_object('hostnameId', $2::int, 'error', $3::text,
+	'timestamp', CURRENT_TIMESTAMP))
+RETURNING
+	id
diff --git a/src/sql/unparsableInsert.sql b/src/sql/unparsableInsert.sql
new file mode 100644
index 0000000..6441f93
--- /dev/null
+++ b/src/sql/unparsableInsert.sql
@@ -0,0 +1,4 @@
+INSERT INTO entities(type, value, detail)
+	VALUES ('unparsable_line', $1, jsonb_build_object('hostnameId', $2::int, 'timestamp', CURRENT_TIMESTAMP))
+RETURNING
+	id
diff --git a/test/test-ingest.cpp b/test/test-ingest.cpp
index b2e1e3e..9c0001b 100644
--- a/test/test-ingest.cpp
+++ b/test/test-ingest.cpp
@@ -504,7 +504,7 @@ BOOST_AUTO_TEST_CASE(FetchMockUserAgentDetail)
 	}
 }
 
-BOOST_AUTO_TEST_CASE(DiscardUnparsable)
+BOOST_AUTO_TEST_CASE(RecordUnparsable)
 {
 	queuedLines.emplace_back("does not parse");
 	auto job = beginIngestQueuedLogLines();
@@ -512,63 +512,110 @@ BOOST_AUTO_TEST_CASE(DiscardUnparsable)
 	BOOST_CHECK(job.second);
 	finishAllJobs();
 	auto dbconn = dbpool->get();
-	auto select = dbconn->select("SELECT id::bigint, value FROM entities WHERE type = 'unparsable_line'");
-	constexpr std::array<std::tuple<EntityId, std::string_view>, 1> EXPECTED {{
-			{18, "does not parse"},
+	auto select = dbconn->select(
+			R"(SELECT id::bigint, value, detail ? 'timestamp' has_ts, (detail->>'hostnameId')::int hostnameId
+			FROM entities
+			WHERE type = 'unparsable_line')");
+	constexpr std::array<std::tuple<EntityId, std::string_view, bool, uint32_t>, 1> EXPECTED {{
+			{18, "does not parse", true, 1},
 	}};
-	auto rows = select->as<EntityId, std::string_view>();
+	auto rows = select->as<EntityId, std::string_view, bool, uint32_t>();
 	BOOST_CHECK_EQUAL_COLLECTIONS(rows.begin(), rows.end(), EXPECTED.begin(), EXPECTED.end());
+	BOOST_CHECK_EQUAL(stats.linesParsed, 0);
 	BOOST_CHECK_EQUAL(stats.linesParseFailed, 1);
-	BOOST_CHECK_EQUAL(stats.entitiesInserted, 1);
+	BOOST_CHECK_EQUAL(stats.entitiesInserted, 0);
 	BOOST_CHECK(existingEntities->empty()); // Don't clutter existing entities with junk logs
 }
 
+BOOST_AUTO_TEST_CASE(RecordUninsertable)
+{
+	auto dbconn = dbpool->get();
+	{ // Part 1: bad HTTP verb causes insert failure after storing entities
+		constexpr std::string_view LOGLINE_UNINSERTABLE
+				= R"LOG(git.randomdan.homeip.net 98.82.40.168 1755561576768319 CAUSEINSERTFAIL "/repo/gentoobrowse-api/commit/gentoobrowse-api/unittests/fixtures/756569aa764177340726dd3d40b41d89b11b20c7/app-crypt/pdfcrack/Manifest" "?h=gentoobrowse-api-0.9.1&id=a2ed3fd30333721accd4b697bfcb6cc4165c7714" HTTP/1.1 200 1884 107791 "-" "Mozilla/5.0 AppleWebKit/537.36 (KHTML, like Gecko; compatible; Amazonbot/0.1; +https://developer.amazon.com/support/amazonbot) Chrome/119.0.6045.214 Safari/537.36" "text/plain")LOG";
+		queuedLines.emplace_back(LOGLINE_UNINSERTABLE);
+		auto job = beginIngestQueuedLogLines();
+		BOOST_CHECK_EQUAL(&job.first, &*storeQueueLines.currentRun);
+		BOOST_CHECK(job.second);
+		finishAllJobs();
+		auto select = dbconn->select(
+				R"(SELECT id::bigint, value, detail ? 'timestamp' has_ts, (detail->>'hostnameId')::int hostnameId, (detail->>'error')::text
+			FROM entities
+			WHERE type = 'uninsertable_line')");
+		constexpr std::array<std::tuple<EntityId, std::string_view, bool, uint32_t, std::string_view>, 1> EXPECTED {{
+				{21, LOGLINE_UNINSERTABLE, true, 1,
+						"ERROR:  invalid input value for enum http_verb: \"CAUSEINSERTFAIL\"\n"
+						"CONTEXT:  unnamed portal parameter $5 = '...'\n"},
+		}};
+		auto rows = select->as<EntityId, std::string_view, bool, uint32_t, std::string_view>();
+		BOOST_CHECK_EQUAL_COLLECTIONS(rows.begin(), rows.end(), EXPECTED.begin(), EXPECTED.end());
+		BOOST_CHECK_EQUAL(stats.linesParsed, 1);
+		BOOST_CHECK_EQUAL(stats.logsInserted, 0);
+		BOOST_CHECK_EQUAL(stats.linesParseFailed, 0);
+		BOOST_CHECK_EQUAL(stats.entitiesInserted, 5); // 5 were inserted, but the savepoint was rolled back
+		BOOST_CHECK(existingEntities->empty()); // ... so existing entities should be empty
+	}
+
+	{ // Part 2: corrected HTTP verb allows insert, requires that the entities are re-stored
+		constexpr std::string_view LOGLINE_UNINSERTABLE_GET
+				= R"LOG(git.randomdan.homeip.net 98.82.40.168 1755561576768320 GET "/repo/gentoobrowse-api/commit/gentoobrowse-api/unittests/fixtures/756569aa764177340726dd3d40b41d89b11b20c7/app-crypt/pdfcrack/Manifest" "?h=gentoobrowse-api-0.9.1&id=a2ed3fd30333721accd4b697bfcb6cc4165c7714" HTTP/1.1 200 1884 107791 "-" "Mozilla/5.0 AppleWebKit/537.36 (KHTML, like Gecko; compatible; Amazonbot/0.1; +https://developer.amazon.com/support/amazonbot) Chrome/119.0.6045.214 Safari/537.36" "text/plain")LOG";
+		queuedLines.emplace_back(LOGLINE_UNINSERTABLE_GET);
+		{
+			auto job = beginIngestQueuedLogLines();
+			BOOST_CHECK_EQUAL(&job.first, &*storeQueueLines.currentRun);
+			BOOST_CHECK(job.second);
+			finishAllJobs();
+		}
+		BOOST_CHECK_EQUAL(stats.linesParsed, 2);
+		BOOST_CHECK_EQUAL(stats.logsInserted, 1);
+		BOOST_CHECK_EQUAL(stats.entitiesInserted, 10);
+		BOOST_CHECK_EQUAL(existingEntities->size(), 5);
+	}
+}
+
 BOOST_AUTO_TEST_CASE(PurgeOldJob)
 {
-	BOOST_CHECK_EQUAL(2, jobPurgeOldLogs()());
+	BOOST_CHECK_EQUAL(3, jobPurgeOldLogs()());
 }
 
-BOOST_AUTO_TEST_CASE(RetryUninsertableNone)
+BOOST_AUTO_TEST_CASE(RetryUninsertableNone, *boost::unit_test::timeout(1))
 {
 	BOOST_CHECK_EQUAL(0, jobRetryUninsertableLines()());
 }
 
-BOOST_AUTO_TEST_CASE(RetryUninsertableSuccess)
+BOOST_AUTO_TEST_CASE(RetryUninsertableSuccess, *boost::unit_test::timeout(1))
 {
 	auto dbconn = dbpool->get();
-	Entity uninsertable {{}, {}, EntityType::UninsertableLine, LOGLINE1};
-	storeNewEntity(dbconn.get(), uninsertable);
-	BOOST_REQUIRE(uninsertable.id);
-	BOOST_REQUIRE(getEntityById(dbconn.get(), *uninsertable.id));
+	const auto uninsertableLineId = storeUninsertableLine(dbconn.get(), LOGLINE1, std::runtime_error {"some error"});
+	BOOST_REQUIRE(getEntityById(dbconn.get(), uninsertableLineId));
 
 	BOOST_CHECK_EQUAL(1, jobRetryUninsertableLines()());
-	BOOST_REQUIRE(!getEntityById(dbconn.get(), *uninsertable.id));
+	BOOST_REQUIRE(!getEntityById(dbconn.get(), uninsertableLineId));
 }
 
-BOOST_AUTO_TEST_CASE(RetryUninsertableNowUnparsable)
+BOOST_AUTO_TEST_CASE(RetryUninsertableNowUnparsable, *boost::unit_test::timeout(1))
 {
 	auto dbconn = dbpool->get();
-	Entity uninsertable {{}, {}, EntityType::UninsertableLine, "blah"};
-	storeNewEntity(dbconn.get(), uninsertable);
-	BOOST_REQUIRE(uninsertable.id);
+	const auto uninsertableId = storeUninsertableLine(dbconn.get(), "blah", std::runtime_error {"some error"});
+	BOOST_REQUIRE(uninsertableId);
 
 	BOOST_CHECK_EQUAL(0, jobRetryUninsertableLines()());
-	auto updatedEntity = getEntityById(dbconn.get(), *uninsertable.id);
+	auto updatedEntity = getEntityById(dbconn.get(), uninsertableId);
 	BOOST_REQUIRE(updatedEntity);
 	BOOST_CHECK_EQUAL(std::get<1>(*updatedEntity), EntityType::UnparsableLine);
 }
 
-BOOST_AUTO_TEST_CASE(RetryUninsertableStillUninsertable)
+BOOST_AUTO_TEST_CASE(RetryUninsertableStillUninsertable, *boost::unit_test::timeout(1))
 {
 	auto dbconn = dbpool->get();
 	constexpr std::string_view LOGLINE_UNINSERTABLE
 			= R"LOG(git.randomdan.homeip.net 98.82.40.168 1755561576768318 CAUSEINSERTFAIL "/repo/gentoobrowse-api/commit/gentoobrowse-api/unittests/fixtures/756569aa764177340726dd3d40b41d89b11b20c7/app-crypt/pdfcrack/Manifest" "?h=gentoobrowse-api-0.9.1&id=a2ed3fd30333721accd4b697bfcb6cc4165c7714" HTTP/1.1 200 1884 107791 "-" "Mozilla/5.0 AppleWebKit/537.36 (KHTML, like Gecko; compatible; Amazonbot/0.1; +https://developer.amazon.com/support/amazonbot) Chrome/119.0.6045.214 Safari/537.36" "text/plain")LOG";
-	Entity uninsertable {{}, {}, EntityType::UninsertableLine, LOGLINE_UNINSERTABLE};
-	storeNewEntity(dbconn.get(), uninsertable);
-	BOOST_REQUIRE(uninsertable.id);
+	const auto uninsertableId
+			= storeUninsertableLine(dbconn.get(), LOGLINE_UNINSERTABLE, std::runtime_error {"some error"});
+	BOOST_REQUIRE(uninsertableId);
 
 	BOOST_CHECK_EQUAL(0, jobRetryUninsertableLines()());
-	auto updatedEntity = getEntityById(dbconn.get(), *uninsertable.id);
+	const auto updatedEntity = getEntityById(dbconn.get(), uninsertableId);
 	BOOST_REQUIRE(updatedEntity);
 	BOOST_CHECK_EQUAL(std::get<1>(*updatedEntity), EntityType::UninsertableLine);
 	const auto & detail = std::get<3>(*updatedEntity);
@@ -600,22 +647,22 @@ using CreateEntitiesData = std::tuple<std::string_view, WebStat::EntityType, int
 
 BOOST_DATA_TEST_CASE(CreateEntities,
 		boost::unit_test::data::make<CreateEntitiesData>({
-				{"host1", WebStat::EntityType::Host, 31},
-				{"host2", WebStat::EntityType::Host, 33},
-				{"host3", WebStat::EntityType::Host, 35},
-				{"host1", WebStat::EntityType::Host, 31},
-				{"host2", WebStat::EntityType::Host, 33},
-				{"host3", WebStat::EntityType::Host, 35},
-				{"host1", WebStat::EntityType::VirtualHost, 40},
-				{"host2", WebStat::EntityType::VirtualHost, 42},
-				{"host3", WebStat::EntityType::VirtualHost, 44},
-				{"host1", WebStat::EntityType::VirtualHost, 40},
-				{"host2", WebStat::EntityType::VirtualHost, 42},
-				{"host3", WebStat::EntityType::VirtualHost, 44},
-				{"host2", WebStat::EntityType::Host, 33},
-				{"host1", WebStat::EntityType::VirtualHost, 40},
-				{"host3", WebStat::EntityType::Host, 35},
-				{"host1", WebStat::EntityType::Host, 31},
+				{"host1", WebStat::EntityType::Host, 34},
+				{"host2", WebStat::EntityType::Host, 36},
+				{"host3", WebStat::EntityType::Host, 38},
+				{"host1", WebStat::EntityType::Host, 34},
+				{"host2", WebStat::EntityType::Host, 36},
+				{"host3", WebStat::EntityType::Host, 38},
+				{"host1", WebStat::EntityType::VirtualHost, 43},
+				{"host2", WebStat::EntityType::VirtualHost, 45},
+				{"host3", WebStat::EntityType::VirtualHost, 47},
+				{"host1", WebStat::EntityType::VirtualHost, 43},
+				{"host2", WebStat::EntityType::VirtualHost, 45},
+				{"host3", WebStat::EntityType::VirtualHost, 47},
+				{"host2", WebStat::EntityType::Host, 36},
+				{"host1", WebStat::EntityType::VirtualHost, 43},
+				{"host3", WebStat::EntityType::Host, 38},
+				{"host1", WebStat::EntityType::Host, 34},
 		}),
 		value, type, expectedId)
 {