log API improvements and queue optimisation for singleton networks

5 files changed, 85 insertions, 47 deletions

diff --git a/include/deliver.php b/include/deliver.php
index 7ff0fa125..04070fe12 100644
--- a/include/deliver.php
+++ b/include/deliver.php
@@ -31,6 +31,7 @@ function deliver_run($argv, $argc) {
 
 			if(($r[0]['outq_posturl'] === z_root() . '/post') && ($r[0]['outq_msg'])) {
 				logger('deliver: local delivery', LOGGER_DEBUG);
+
 				// local delivery
 				// we should probably batch these and save a few delivery processes
 
diff --git a/include/notifier.php b/include/notifier.php
index 036fcbfc8..32d702cb5 100644
--- a/include/notifier.php
+++ b/include/notifier.php
@@ -189,7 +189,6 @@ function notifier_run($argv, $argc){
 					$private = false;
 					$packet_type = 'refresh';
 					$packet_recips = array(array('guid' => $r[0]['xchan_guid'],'guid_sig' => $r[0]['xchan_guid_sig'],'hash' => $r[0]['xchan_hash']));
-
 				}
 			}
 		}
@@ -299,7 +298,7 @@ function notifier_run($argv, $argc){
 			$channel = $s[0];
 
 		if($channel['channel_hash'] !== $target_item['author_xchan'] && $channel['channel_hash'] !== $target_item['owner_xchan']) {
-			logger("notifier: Sending channel {$channel['channel_hash']} is not owner {$target_item['owner_xchan']} or author {$target_item['author_xchan']}");
+			logger("notifier: Sending channel {$channel['channel_hash']} is not owner {$target_item['owner_xchan']} or author {$target_item['author_xchan']}", LOGGER_NORMAL, LOG_WARNING);
 			return;
 		}
 
@@ -318,7 +317,7 @@ function notifier_run($argv, $argc){
 				return;
 
 			if(strpos($r[0]['postopts'],'nodeliver') !== false) {
-				logger('notifier: target item is undeliverable', LOGGER_DEBUG);
+				logger('notifier: target item is undeliverable', LOGGER_DEBUG, LOG_NOTICE);
 				return;
 			}
 
@@ -354,8 +353,8 @@ function notifier_run($argv, $argc){
 		// $cmd === 'relay' indicates the owner is sending it to the original recipients
 		// don't allow the item in the relay command to relay to owner under any circumstances, it will loop
 
-		logger('notifier: relay_to_owner: ' . (($relay_to_owner) ? 'true' : 'false'), LOGGER_DATA);
-		logger('notifier: top_level_post: ' . (($top_level_post) ? 'true' : 'false'), LOGGER_DATA);
+		logger('notifier: relay_to_owner: ' . (($relay_to_owner) ? 'true' : 'false'), LOGGER_DATA, LOG_DEBUG);
+		logger('notifier: top_level_post: ' . (($top_level_post) ? 'true' : 'false'), LOGGER_DATA, LOG_DEBUG);
 
 		// tag_deliver'd post which needs to be sent back to the original author
 
@@ -397,7 +396,7 @@ function notifier_run($argv, $argc){
 			// TODO verify this is needed - copied logic from same place in old code
 
 			if(intval($target_item['item_deleted']) && (! intval($target_item['item_wall']))) {
-				logger('notifier: ignoring delete notification for non-wall item');
+				logger('notifier: ignoring delete notification for non-wall item', LOGGER_NORMAL, LOG_NOTICE);
 				return;
 			}
 		}
@@ -412,13 +411,13 @@ function notifier_run($argv, $argc){
 	$x = $encoded_item;
 	$x['title'] = 'private';
 	$x['body'] = 'private';
-	logger('notifier: encoded item: ' . print_r($x,true), LOGGER_DATA);
+	logger('notifier: encoded item: ' . print_r($x,true), LOGGER_DATA, LOG_DEBUG);
 
 	stringify_array_elms($recipients);
 	if(! $recipients)
 		return;
 
-//	logger('notifier: recipients: ' . print_r($recipients,true));
+//	logger('notifier: recipients: ' . print_r($recipients,true), LOGGER_NORMAL, LOG_DEBUG);
 
 	$env_recips = (($private) ? array() : null);
 
@@ -446,7 +445,7 @@ function notifier_run($argv, $argc){
 
 	if(($private) && (! $env_recips)) {
 		// shouldn't happen
-		logger('notifier: private message with no envelope recipients.' . print_r($argv,true));
+		logger('notifier: private message with no envelope recipients.' . print_r($argv,true), LOGGER_NORMAL, LOG_NOTICE);
 	}
 	
 	logger('notifier: recipients (may be delivered to more if public): ' . print_r($recip_list,true), LOGGER_DEBUG);
@@ -461,7 +460,7 @@ function notifier_run($argv, $argc){
  
 
 	if(! $r) {
-		logger('notifier: no hubs');
+		logger('notifier: no hubs', LOGGER_NORMAL, LOG_NOTICE);
 		return;
 	}
 
@@ -484,7 +483,7 @@ function notifier_run($argv, $argc){
 
 	foreach($hubs as $hub) {
 		if(in_array($hub['hubloc_url'],$dead_hubs)) {
-			logger('skipping dead hub: ' . $hub['hubloc_url'], LOGGER_DEBUG);
+			logger('skipping dead hub: ' . $hub['hubloc_url'], LOGGER_DEBUG, LOG_INFO);
 			continue;
 		}
 
@@ -504,7 +503,7 @@ function notifier_run($argv, $argc){
 		}
 	}
 
-	logger('notifier: will notify/deliver to these hubs: ' . print_r($hublist,true), LOGGER_DEBUG);
+	logger('notifier: will notify/deliver to these hubs: ' . print_r($hublist,true), LOGGER_DEBUG, LOG_DEBUG);
 			 
 
 	foreach($dhubs as $hub) {
@@ -514,6 +513,7 @@ function notifier_run($argv, $argc){
 			$narr = array(
 				'channel' => $channel,
 				'env_recips' => $env_recips,
+				'packet_recips' => $packet_recips,
 				'recipients' => $recipients,
 				'item' => $item,
 				'target_item' => $target_item,
diff --git a/include/queue_fn.php b/include/queue_fn.php
index 92299a193..0708aab56 100644
--- a/include/queue_fn.php
+++ b/include/queue_fn.php
@@ -124,6 +124,26 @@ function queue_deliver($outq, $immediate = false) {
 				dbesc($outq['outq_hash'])
 			);
 			remove_queue_item($outq['outq_hash']);
+
+			// server is responding - see if anything else is going to this destination and is piled up 
+			// and try to send some more. We're relying on the fact that delivery_loop() results in an 
+			// immediate delivery otherwise we could get into a queue loop. 
+
+			if(! $immediate) {
+				$x = q("select outq_hash from outq where outq_posturl = '%s' and outq_delivered = 0",
+					dbesc($outq['outq_posturl'])
+				);
+
+				$piled_up = array();
+				if($x) {
+					foreach($x as $xx) {
+						 $piled_up[] = $xx['outq_hash'];
+					}
+				}
+				if($piled_up) {
+					delivery_loop($piled_up);
+				}
+			}
 		}
 		else {
 			logger('deliver: queue post returned ' . $result['return_code'] 
diff --git a/include/text.php b/include/text.php
index 4b82343eb..fb8ea3c28 100644
--- a/include/text.php
+++ b/include/text.php
@@ -538,7 +538,7 @@ function attribute_contains($attr, $s) {
  * @param int $level A log level.
  */
 
-function logger($msg, $level = 0) {
+function logger($msg, $level = LOGGER_NORMAL, $priority = LOG_INFO) {
 	// turn off logger in install mode
 	global $a;
 	global $db;
@@ -559,8 +559,8 @@ function logger($msg, $level = 0) {
 		$where = basename($stack[0]['file']) . ':' . $stack[0]['line'] . ':' . $stack[1]['function'] . ': ';
 	}
 
-	$s = datetime_convert() . ':' . session_id() . ' ' . $where . $msg . PHP_EOL;
-	$pluginfo = array('filename' => $logfile, 'loglevel' => $level, 'message' => $s,'logged' => false);
+	$s = datetime_convert() . ':' . log_priority_str($priority) . ':' . session_id() . ':' . $where . $msg . PHP_EOL;
+	$pluginfo = array('filename' => $logfile, 'loglevel' => $level, 'message' => $s,'priority' => $priority, 'logged' => false);
 
 	call_hooks('logger',$pluginfo);
 
@@ -568,6 +568,23 @@ function logger($msg, $level = 0) {
 		@file_put_contents($pluginfo['filename'], $pluginfo['message'], FILE_APPEND);
 }
 
+function log_priority_str($priority) {
+	$parr = array(
+		LOG_EMERG   => 'LOG_EMERG',
+		LOG_ALERT   => 'LOG_ALERT',
+		LOG_CRIT    => 'LOG_CRIT',
+		LOG_ERR     => 'LOG_ERR',
+		LOG_WARNING => 'LOG_WARNING',
+		LOG_NOTICE  => 'LOG_NOTICE',
+		LOG_INFO    => 'LOG_INFO',
+		LOG_DEBUG   => 'LOG_DEBUG'
+	);
+
+	if($parr[$priority])
+		return $parr[$priority];
+	return 'LOG_UNDEFINED';
+}
+
 /**
  * @brief This is a special logging facility for developers.
  *
diff --git a/include/zot.php b/include/zot.php
index 922637bc1..a644bbd06 100644
--- a/include/zot.php
+++ b/include/zot.php
@@ -142,7 +142,7 @@ function zot_build_packet($channel, $type = 'notify', $recipients = null, $remot
 			$data[$k] = $v;
 	}
 
-	logger('zot_build_packet: ' . print_r($data,true), LOGGER_DATA);
+	logger('zot_build_packet: ' . print_r($data,true), LOGGER_DATA, LOG_DEBUG);
 
 	// Hush-hush ultra top-secret mode
 
@@ -194,7 +194,7 @@ function zot_finger($webbie, $channel = null, $autofallback = true) {
 		logger('zot_finger: no address :' . $webbie);
 		return array('success' => false);
 	}
-	logger('using xchan_addr: ' . $xchan_addr, LOGGER_DATA);
+	logger('using xchan_addr: ' . $xchan_addr, LOGGER_DATA, LOG_DEBUG);
 
 	// potential issue here; the xchan_addr points to the primary hub.
 	// The webbie we were called with may not, so it might not be found
@@ -211,7 +211,7 @@ function zot_finger($webbie, $channel = null, $autofallback = true) {
 
 		if ($r[0]['hubloc_network'] && $r[0]['hubloc_network'] !== 'zot') {
 			logger('zot_finger: alternate network: ' . $webbie);
-			logger('url: '.$url.', net: '.var_export($r[0]['hubloc_network'],true), LOGGER_DATA);
+			logger('url: '.$url.', net: '.var_export($r[0]['hubloc_network'],true), LOGGER_DATA, LOG_DEBUG);
 			return array('success' => false);
 		}
 	} else {
@@ -288,9 +288,9 @@ function zot_refresh($them, $channel = null, $force = false) {
 		return true;
 	}
 
-	logger('zot_refresh: them: ' . print_r($them,true), LOGGER_DATA);
+	logger('zot_refresh: them: ' . print_r($them,true), LOGGER_DATA, LOG_DEBUG);
 	if ($channel)
-		logger('zot_refresh: channel: ' . print_r($channel,true), LOGGER_DATA);
+		logger('zot_refresh: channel: ' . print_r($channel,true), LOGGER_DATA, LOG_DEBUG);
 
 	$url = null;
 
@@ -353,7 +353,7 @@ function zot_refresh($them, $channel = null, $force = false) {
 
 	$result = z_post_url($url . $rhs,$postvars);
 
-	logger('zot_refresh: zot-info: ' . print_r($result,true), LOGGER_DATA);
+	logger('zot_refresh: zot-info: ' . print_r($result,true), LOGGER_DATA, LOG_DEBUG);
 
 	if ($result['success']) {
 
@@ -381,7 +381,7 @@ function zot_refresh($them, $channel = null, $force = false) {
 					$channel['channel_prvkey']);
 				if($permissions)
 					$permissions = json_decode($permissions,true);
-				logger('decrypted permissions: ' . print_r($permissions,true), LOGGER_DATA);
+				logger('decrypted permissions: ' . print_r($permissions,true), LOGGER_DATA, LOG_DEBUG);
 			}
 			else
 				$permissions = $j['permissions'];
@@ -614,7 +614,7 @@ function zot_register_hub($arr) {
 
 		$x = z_fetch_url($url);
 
-		logger('zot_register_hub: ' . print_r($x,true), LOGGER_DATA);
+		logger('zot_register_hub: ' . print_r($x,true), LOGGER_DATA, LOG_DEBUG);
 
 		if($x['success']) {
 			$record = json_decode($x['body'],true);
@@ -754,8 +754,8 @@ function import_xchan($arr,$ud_flags = UPDATE_FLAGS_UPDATED, $ud_arr = null) {
 				dbesc($xchan_hash)
 			);
 
-			logger('import_xchan: update: existing: ' . print_r($r[0],true), LOGGER_DATA);
-			logger('import_xchan: update: new: ' . print_r($arr,true), LOGGER_DATA);
+			logger('import_xchan: update: existing: ' . print_r($r[0],true), LOGGER_DATA, LOG_DEBUG);
+			logger('import_xchan: update: new: ' . print_r($arr,true), LOGGER_DATA, LOG_DEBUG);
 			$what .= 'xchan ';
 			$changed = true;
 		}
@@ -955,7 +955,7 @@ function import_xchan($arr,$ud_flags = UPDATE_FLAGS_UPDATED, $ud_arr = null) {
 		$ret['hash'] = $xchan_hash;
 	}
 
-	logger('import_xchan: result: ' . print_r($ret,true), LOGGER_DATA);
+	logger('import_xchan: result: ' . print_r($ret,true), LOGGER_DATA, LOG_DEBUG);
 	return $ret;
 }
 
@@ -980,7 +980,7 @@ function zot_process_response($hub, $arr, $outq) {
 
 	if (! $x) {
 		logger('zot_process_response: No json from ' . $hub);
-		logger('zot_process_response: headers: ' . print_r($arr['header'],true), LOGGER_DATA);
+		logger('zot_process_response: headers: ' . print_r($arr['header'],true), LOGGER_DATA, LOG_DEBUG);
 	}
 
 	if(is_array($x) && array_key_exists('delivery_report',$x) && is_array($x['delivery_report'])) {
@@ -1015,7 +1015,7 @@ function zot_process_response($hub, $arr, $outq) {
 	// async messages remain in the queue until processed.
 
 	if(intval($outq['outq_async']))
-		queue_set_delivered($outq['outq_hash'],$outq['outq_channel']);
+		remove_queue_item($outq['outq_hash'],$outq['outq_channel']);
 
 	logger('zot_process_response: ' . print_r($x,true), LOGGER_DEBUG);
 }
@@ -1037,7 +1037,7 @@ function zot_process_response($hub, $arr, $outq) {
  */
 function zot_fetch($arr) {
 
-	logger('zot_fetch: ' . print_r($arr,true), LOGGER_DATA);
+	logger('zot_fetch: ' . print_r($arr,true), LOGGER_DATA, LOG_DEBUG);
 
 	$url = $arr['sender']['url'] . $arr['callback'];
 
@@ -1134,7 +1134,7 @@ function zot_import($arr, $sender_url) {
 				$i['notify'] = json_decode(crypto_unencapsulate($i['notify'],get_config('system','prvkey')),true);
 			}
 
-			logger('zot_import: notify: ' . print_r($i['notify'],true), LOGGER_DATA);
+			logger('zot_import: notify: ' . print_r($i['notify'],true), LOGGER_DATA, LOG_DEBUG);
 
 			$hub = zot_gethub($i['notify']['sender']);
 			if((! $hub) || ($hub['hubloc_url'] != $sender_url)) {
@@ -1151,7 +1151,7 @@ function zot_import($arr, $sender_url) {
 
 			if(array_key_exists('message',$i) && array_key_exists('type',$i['message']) && $i['message']['type'] === 'rating') {
 				// rating messages are processed only by directory servers
-				logger('Rating received: ' . print_r($arr,true), LOGGER_DATA);
+				logger('Rating received: ' . print_r($arr,true), LOGGER_DATA, LOG_DEBUG);
 				$result = process_rating_delivery($i['notify']['sender'],$i['message']);
 				continue;
 			}
@@ -1261,8 +1261,8 @@ function zot_import($arr, $sender_url) {
 						continue;
 					}
 
-					logger('Activity received: ' . print_r($arr,true), LOGGER_DATA);
-					logger('Activity recipients: ' . print_r($deliveries,true), LOGGER_DATA);
+					logger('Activity received: ' . print_r($arr,true), LOGGER_DATA, LOG_DEBUG);
+					logger('Activity recipients: ' . print_r($deliveries,true), LOGGER_DATA, LOG_DEBUG);
 
 					$relay = ((array_key_exists('flags',$i['message']) && in_array('relay',$i['message']['flags'])) ? true : false);
 					$result = process_delivery($i['notify']['sender'],$arr,$deliveries,$relay,false,$message_request);
@@ -1270,16 +1270,16 @@ function zot_import($arr, $sender_url) {
 				elseif($i['message']['type'] === 'mail') {
 					$arr = get_mail_elements($i['message']);
 
-					logger('Mail received: ' . print_r($arr,true), LOGGER_DATA);
-					logger('Mail recipients: ' . print_r($deliveries,true), LOGGER_DATA);
+					logger('Mail received: ' . print_r($arr,true), LOGGER_DATA, LOG_DEBUG);
+					logger('Mail recipients: ' . print_r($deliveries,true), LOGGER_DATA, LOG_DEBUG);
 
 					$result = process_mail_delivery($i['notify']['sender'],$arr,$deliveries);
 				}
 				elseif($i['message']['type'] === 'profile') {
 					$arr = get_profile_elements($i['message']);
 
-					logger('Profile received: ' . print_r($arr,true), LOGGER_DATA);
-					logger('Profile recipients: ' . print_r($deliveries,true), LOGGER_DATA);
+					logger('Profile received: ' . print_r($arr,true), LOGGER_DATA, LOG_DEBUG);
+					logger('Profile recipients: ' . print_r($deliveries,true), LOGGER_DATA, LOG_DEBUG);
 
 					$result = process_profile_delivery($i['notify']['sender'],$arr,$deliveries);
 				}
@@ -1288,16 +1288,16 @@ function zot_import($arr, $sender_url) {
 
 					$arr = $i['message'];
 
-					logger('Channel sync received: ' . print_r($arr,true), LOGGER_DATA);
-					logger('Channel sync recipients: ' . print_r($deliveries,true), LOGGER_DATA);
+					logger('Channel sync received: ' . print_r($arr,true), LOGGER_DATA, LOG_DEBUG);
+					logger('Channel sync recipients: ' . print_r($deliveries,true), LOGGER_DATA, LOG_DEBUG);
 
 					$result = process_channel_sync_delivery($i['notify']['sender'],$arr,$deliveries);
 				}
 				elseif($i['message']['type'] === 'location') {
 					$arr = $i['message'];
 
-					logger('Location message received: ' . print_r($arr,true), LOGGER_DATA);
-					logger('Location message recipients: ' . print_r($deliveries,true), LOGGER_DATA);
+					logger('Location message received: ' . print_r($arr,true), LOGGER_DATA, LOG_DEBUG);
+					logger('Location message recipients: ' . print_r($deliveries,true), LOGGER_DATA, LOG_DEBUG);
 
 					$result = process_location_delivery($i['notify']['sender'],$arr,$deliveries);
 				}
@@ -1483,7 +1483,7 @@ function public_recips($msg) {
 		}
 	}
 
-	logger('public_recips: ' . print_r($r,true), LOGGER_DATA);
+	logger('public_recips: ' . print_r($r,true), LOGGER_DATA, LOG_DEBUG);
 	return $r;
 }
 
@@ -1501,7 +1501,7 @@ function public_recips($msg) {
  */
 function allowed_public_recips($msg) {
 
-	logger('allowed_public_recips: ' . print_r($msg,true),LOGGER_DATA);
+	logger('allowed_public_recips: ' . print_r($msg,true),LOGGER_DATA, LOG_DEBUG);
 
 	if(array_key_exists('public_scope',$msg['message']))
 		$scope = $msg['message']['public_scope'];
@@ -2873,7 +2873,7 @@ function build_sync_packet($uid = 0, $packet = null, $groups_changed = false) {
 	logger('build_sync_packet');
 
 	if($packet)
-		logger('packet: ' . print_r($packet, true),LOGGER_DATA);
+		logger('packet: ' . print_r($packet, true),LOGGER_DATA, LOG_DEBUG);
 
 	if(! $uid)
 		$uid = local_channel();
@@ -2967,7 +2967,7 @@ function build_sync_packet($uid = 0, $packet = null, $groups_changed = false) {
 	$interval = ((get_config('system','delivery_interval') !== false)
 			? intval(get_config('system','delivery_interval')) : 2 );
 
-	logger('build_sync_packet: packet: ' . print_r($info,true), LOGGER_DATA);
+	logger('build_sync_packet: packet: ' . print_r($info,true), LOGGER_DATA, LOG_DEBUG);
 
 	foreach($synchubs as $hub) {
 		$hash = random_string();
@@ -3864,7 +3864,7 @@ function zotinfo($arr) {
 function check_zotinfo($channel,$locations,&$ret) {
 
 
-//	logger('locations: ' . print_r($locations,true),LOGGER_DATA);
+//	logger('locations: ' . print_r($locations,true),LOGGER_DATA, LOG_DEBUG);
 
 	// This function will likely expand as we find more things to detect and fix.
 	// 1. Because magic-auth is reliant on it, ensure that the system channel has a valid hubloc
@@ -4085,7 +4085,7 @@ function zot_reply_pickup($data) {
 
 		$sitekey = $hubsite['hubloc_sitekey'];
 
-		logger('mod_zot: Checking sitekey: ' . $sitekey, LOGGER_DATA);
+		logger('mod_zot: Checking sitekey: ' . $sitekey, LOGGER_DATA, LOG_DEBUG);
 
 		if(rsa_verify($data['callback'],base64url_decode($data['callback_sig']),$sitekey)) {
 			$forgery = false;