diff --git a/server/SHServ/Controllers/AreasRESTAPIController.php b/server/SHServ/Controllers/AreasRESTAPIController.php index 8d8536c..120b4c1 100644 --- a/server/SHServ/Controllers/AreasRESTAPIController.php +++ b/server/SHServ/Controllers/AreasRESTAPIController.php @@ -39,6 +39,7 @@ $response[] = $area -> to_array(); } + logging() -> trace('php:Areas', 'Areas list fetched', ['total' => count($response)]); return $this -> utils() -> response_success([ "areas" => $response, "total" => count($response) @@ -57,10 +58,12 @@ $areas_model = new Areas(); if(!preg_match('/^[a-z0-9_]+$/', $alias) || strlen($alias) > 255) { + logging() -> warn('php:Areas', 'New area failed: invalid alias', ['alias' => $alias]); return $this -> utils() -> response_error("invalid_alias", ["alias"]); } if(!$areas_model -> alias_is_uniq($alias)) { + logging() -> warn('php:Areas', 'New area failed: alias already exists', ['alias' => $alias]); return $this -> utils() -> response_error("alias_already_exists", ["alias"]); } @@ -75,9 +78,11 @@ $area = $areas_model -> create_new_area($type, $alias, $display_name); if(!$area) { + logging() -> warn('php:Areas', 'New area failed: creation error', ['alias' => $alias]); return $this -> utils() -> response_error("area_not_exists"); } + logging() -> info('php:Areas', 'New area created', ['area_id' => $area -> id(), 'alias' => $area -> alias, 'type' => $type]); return $this -> utils() -> response_success([ "alias" => $area -> alias, "area" => $area -> to_array() @@ -98,10 +103,14 @@ $area = new Area(intval($area_id)); if(!$area) { + logging() -> warn('php:Areas', 'Remove area failed: not found', ['area_id' => $area_id]); return $this -> utils() -> response_error("area_not_exists"); } + logging() -> warn('php:Areas', 'Remove area', ['area_id' => $area -> id(), 'alias' => $area -> alias]); + if(!$area -> remove()) { + logging() -> warn('php:Areas', 'Remove area failed', ['area_id' => $area -> id()]); return $this -> utils() -> response_error("undefined_error"); } @@ -127,10 +136,14 @@ $place_area = new Area(intval($place_in_area_id)); if(!$target_area or !$place_area) { + logging() -> warn('php:Areas', 'Place area in area failed: not found', ['target_id' => $target_id, 'place_in_area_id' => $place_in_area_id]); return $this -> utils() -> response_error("area_not_exists"); } + logging() -> info('php:Areas', 'Place area in area', ['target_id' => $target_area -> id(), 'target_alias' => $target_area -> alias, 'parent_id' => $place_area -> id()]); + if(!$target_area -> place_in_area($place_area)) { + logging() -> warn('php:Areas', 'Place area in area failed', ['target_id' => $target_area -> id(), 'parent_id' => $place_area -> id()]); return $this -> utils() -> response_error("undefined_error"); } @@ -156,13 +169,16 @@ $area = new Area(intval($area_id)); if(!$area) { + logging() -> warn('php:Areas', 'Update area display name failed: not found', ['area_id' => $area_id]); return $this -> utils() -> response_error("area_not_exists"); } + logging() -> info('php:Areas', 'Update area display name', ['area_id' => $area -> id(), 'alias' => $area -> alias, 'display_name' => $display_name]); + $area -> display_name = $display_name; return $area -> update() - ? $this -> utils() -> response_success([ + ? $this -> utils() -> response_success([ "alias" => $area -> alias, "area" => $area -> to_array() ]) @@ -183,27 +199,32 @@ } if(!preg_match('/^[a-z0-9_]+$/', $new_alias) || strlen($new_alias) > 255) { + logging() -> warn('php:Areas', 'Update area alias failed: invalid alias', ['area_id' => $area_id, 'new_alias' => $new_alias]); return $this -> utils() -> response_error("invalid_alias", ["new_alias"]); } $areas_model = new Areas(); if(!$areas_model -> alias_is_uniq($new_alias, intval($area_id))) { + logging() -> warn('php:Areas', 'Update area alias failed: already exists', ['area_id' => $area_id, 'new_alias' => $new_alias]); return $this -> utils() -> response_error("alias_already_exists", ["alias"]); } $area = new Area(intval($area_id)); if(!$area) { + logging() -> warn('php:Areas', 'Update area alias failed: not found', ['area_id' => $area_id]); return $this -> utils() -> response_error("area_not_exists"); } + logging() -> info('php:Areas', 'Update area alias', ['area_id' => $area -> id(), 'old_alias' => $area -> alias, 'new_alias' => $new_alias]); + $area -> alias = $new_alias; return $area -> update() - ? $this -> utils() -> response_success([ + ? $this -> utils() -> response_success([ "alias" => $area -> alias, - "area" => $area -> to_array() + "area" => $area -> to_array() ]) : $this -> utils() -> response_error("undefined_error"); } @@ -219,11 +240,14 @@ $area = new Area(intval($area_id)); if(!$area) { + logging() -> warn('php:Areas', 'Reboot devices in area failed: not found', ['area_id' => $area_id]); return $this -> utils() -> response_error("area_not_exists"); } $devices = $area -> get_inner_devices(true); + logging() -> info('php:Areas', 'Reboot devices in area', ['area_id' => $area -> id(), 'alias' => $area -> alias, 'count' => count($devices)]); + $results = []; foreach($devices as $device) { $results["{$area -> alias}:{$device -> alias}"] = $device -> device_api() -> reboot(); @@ -254,6 +278,8 @@ $devices = $area -> get_inner_devices(true); + logging() -> trace('php:Areas', 'Devices in area fetched', ['area_id' => $area_id, 'total' => count($devices)]); + return $this -> utils() -> response_success([ "devices" => array_map(function($device) { return $device -> to_array(); @@ -287,7 +313,7 @@ $scripts = $area -> get_inner_scripts(true); $response_scripts = array_map(function($script) use ($scripts_base) { - return isset($scripts_base[$script -> type][$script -> uniq_name]) + return isset($scripts_base[$script -> type][$script -> uniq_name]) ? $script -> prepare_to_view($scripts_base[$script -> type][$script -> uniq_name]) : false; }, $scripts); @@ -296,6 +322,8 @@ return $item != false; })); + logging() -> trace('php:Areas', 'Scripts in area fetched', ['area_id' => $area_id, 'total' => count($scripts)]); + return $this -> utils() -> response_success([ "scripts" => $response_scripts, "total" => count($scripts) @@ -316,9 +344,12 @@ $area = new Area(intval($target_id)); if(!$area) { + logging() -> warn('php:Areas', 'Unassign area failed: not found', ['area_id' => $target_id]); return $this -> utils() -> response_error("area_not_exists"); } + logging() -> info('php:Areas', 'Unassign area', ['area_id' => $area -> id(), 'alias' => $area -> alias]); + return $area -> place_in_area_id(0) ? $this -> utils() -> response_success() : $this -> utils() -> response_error("undefined_error"); @@ -331,8 +362,10 @@ */ public function exists_types() { if ($auth = $this -> require_permission('areas.view')) { return $auth; } + $types = (new Areas()) -> get_exists_types(); + logging() -> trace('php:Areas', 'Area types fetched', ['total' => count($types)]); return $this -> utils() -> response_success([ - "types" => (new Areas()) -> get_exists_types() + "types" => $types ]); } } diff --git a/server/SHServ/Controllers/AuthController.php b/server/SHServ/Controllers/AuthController.php index 60e0bf1..542cc39 100644 --- a/server/SHServ/Controllers/AuthController.php +++ b/server/SHServ/Controllers/AuthController.php @@ -31,6 +31,12 @@ $returnTo = $_GET['return_to'] ?? '/'; $returnTo = $this->sanitizeReturnTo($returnTo); $url = $service->buildLoginUrl($returnTo); + + logging()->info('php:Auth', 'Login attempt', [ + 'client_ip' => $_SERVER['REMOTE_ADDR'] ?? '0.0.0.0', + 'return_to' => $returnTo, + ]); + return $this->utils()->redirect($url); } @@ -61,12 +67,22 @@ try { $user = $service->handleCallback($code, $state); } catch (\GNexus\GAuth\Exception\GAuthException $e) { + logging()->warn('php:Auth', 'OAuth callback failed', [ + 'message' => $e->getMessage(), + 'client_ip' => $_SERVER['REMOTE_ADDR'] ?? '0.0.0.0', + ]); return $this->utils()->response_error('auth_failed', [], ['message' => $e->getMessage()]); } $resolver = new UserResolver(); $localUserId = $resolver->resolve($user); + logging()->info('php:Auth', 'OAuth login successful', [ + 'user_id' => $localUserId, + 'email' => $user->email, + 'gauth_user_id' => $user->userId, + ]); + $_SESSION['shserv_user_id'] = $localUserId; // Persist tokens to DB now that we have the local user ID @@ -120,6 +136,8 @@ public function logout() { $sessionToken = $_SESSION['shserv_auth_token'] ?? null; + $currentUser = $this->get_current_user(); + $userId = $currentUser['id'] ?? null; if (!$sessionToken) { $bearer = $this->get_bearer_token(); @@ -140,7 +158,10 @@ try { $service->getClient()->revokeToken($tokenSet->refreshToken, 'refresh_token'); } catch (\Throwable $e) { - // ignore revoke failures during logout + logging()->warn('php:Auth', 'Token revoke failed during logout', [ + 'user_id' => $userId, + 'message' => $e->getMessage(), + ]); } } $dbStore->forget($sessionToken); @@ -174,6 +195,8 @@ session_destroy(); + logging()->info('php:Auth', 'Logout', ['user_id' => $userId]); + return $this->utils()->response_success(); } @@ -188,6 +211,8 @@ return $this->utils()->response_error('not_found_any_sessions', [], [], 401); } + logging()->trace('php:Auth', 'Auth me request', ['user_id' => $user['id']]); + $permissions = $this->get_current_permissions(); $gauthBase = FCONF['gauth']['base_url'] ?? ''; @@ -215,6 +240,10 @@ $limiter = new RateLimiter('shserv_auth_', 10, 60); $clientIp = $_SERVER['REMOTE_ADDR'] ?? '0.0.0.0'; if (!$limiter->check($action . ':' . $clientIp)) { + logging()->warn('php:Auth', 'Auth rate limit exceeded', [ + 'action' => $action, + 'client_ip' => $clientIp, + ]); return $this->utils()->response_error('rate_limit', [], [], 429); } return null; @@ -240,6 +269,9 @@ } if (!$sessionToken) { + logging()->warn('php:Auth', 'Token refresh failed: no session', [ + 'client_ip' => $_SERVER['REMOTE_ADDR'] ?? '0.0.0.0', + ]); return $this->utils()->response_error('not_found_any_sessions', [], [], 401); } @@ -247,9 +279,16 @@ $tokenSet = $service->refreshAccessToken($sessionToken); if (!$tokenSet) { + logging()->warn('php:Auth', 'Token refresh failed: session expired', [ + 'session_token' => substr($sessionToken, 0, 8) . '...', + ]); return $this->utils()->response_error('session_expired', [], [], 401); } + logging()->info('php:Auth', 'Token refresh successful', [ + 'expires_in' => $tokenSet->expiresIn, + ]); + return $this->utils()->response_success([ 'access_token' => $tokenSet->accessToken, 'expires_in' => $tokenSet->expiresIn, diff --git a/server/SHServ/Controllers/DevicesRESTAPIController.php b/server/SHServ/Controllers/DevicesRESTAPIController.php index 612ad0a..9552109 100644 --- a/server/SHServ/Controllers/DevicesRESTAPIController.php +++ b/server/SHServ/Controllers/DevicesRESTAPIController.php @@ -66,6 +66,8 @@ $device_model = new Devices(); $devices = $device_model -> get_unregistered_devices(); + logging() -> debug('php:Devices', 'Scan ready_to_setup finished', ['found' => count($devices)]); + return $this -> utils() -> response_success([ "devices" => $devices ]); @@ -81,6 +83,8 @@ // Update IP / connection_status for active devices that changed their address $device_model -> reconcile_scan_results($devices); + logging() -> debug('php:Devices', 'Scan all finished', ['found' => count($devices)]); + return $this -> utils() -> response_success([ "devices" => $devices ]); @@ -96,24 +100,31 @@ list($host, ) = explode(':', $device_ip, 2); } if(!filter_var($host, FILTER_VALIDATE_IP, FILTER_FLAG_IPV4)) { + logging() -> warn('php:Devices', 'Setup new device failed: invalid IP', ['device_ip' => $device_ip]); return $this -> utils() -> response_error("invalid_ip", ["device_ip"]); } if(!preg_match('/^[a-z0-9_]+$/', $alias) || strlen($alias) > 255) { + logging() -> warn('php:Devices', 'Setup new device failed: invalid alias', ['alias' => $alias]); return $this -> utils() -> response_error("invalid_alias", ["alias"]); } if(!strlen($name) || strlen($name) > 255) { + logging() -> warn('php:Devices', 'Setup new device failed: empty name', ['name' => $name]); return $this -> utils() -> response_error("empty_field", ["name"]); } if(!$devices_model -> alias_is_uniq($alias)) { + logging() -> warn('php:Devices', 'Setup new device failed: alias already exists', ['alias' => $alias]); return $this -> utils() -> response_error("alias_already_exists", ["alias"]); } + logging() -> info('php:Devices', 'Setup new device attempt', ['device_ip' => $device_ip, 'alias' => $alias]); + $result = $devices_model -> connect_new_device($device_ip, $alias, $name, $description); if($result and $result instanceof \SHServ\Entities\Device) { + logging() -> info('php:Devices', 'Setup new device successful', ['device_id' => $result -> id(), 'alias' => $result -> alias]); $device_about = $result -> device_api() -> get_about(); return $this -> utils() -> response_success([ "device" => [ @@ -126,6 +137,7 @@ ]); } + logging() -> warn('php:Devices', 'Setup new device failed', ['device_ip' => $device_ip, 'alias' => $alias, 'error' => $result["err_alias"] ?? 'unknown']); return $this -> utils() -> response_error($result["err_alias"]); } @@ -136,12 +148,16 @@ $device = $devices_model -> by_id(intval($device_id)); if(!$device) { + logging() -> warn('php:Devices', 'Resetup device failed: not found', ['device_id' => $device_id]); return $this -> utils() -> response_error("device_not_found"); } + logging() -> info('php:Devices', 'Resetup device', ['device_id' => $device -> id(), 'alias' => $device -> alias]); + $result = $devices_model -> resetup_device($device); if($result) { + logging() -> info('php:Devices', 'Resetup device successful', ['device_id' => $device -> id()]); $device_about = $device -> device_api() -> get_about(); return $this -> utils() -> response_success([ "device" => [ @@ -154,22 +170,27 @@ ]); } + logging() -> warn('php:Devices', 'Resetup device failed', ['device_id' => $device_id]); return $this -> utils() -> response_error(); } public function remove_device($device_id) { if ($auth = $this -> require_permission('devices.delete')) { return $auth; } $devices_model = new Devices(); + + logging() -> warn('php:Devices', 'Remove device attempt', ['device_id' => $device_id]); $result = $devices_model -> remove_device(intval($device_id)); if(!$result["result"]) { + logging() -> warn('php:Devices', 'Remove device failed', ['device_id' => $device_id, 'error' => $result["err_alias"] ?? 'unknown', 'device_msg' => $result["device_msg"] ?? '']); return $this -> utils() -> response_error( - $result["err_alias"], - [], + $result["err_alias"], + [], [ "device_msg" => $result["device_msg"] ] ); } + logging() -> info('php:Devices', 'Remove device successful', ['device_id' => $device_id, 'device_msg' => $result["device_msg"]]); return $this -> utils() -> response_success([ "result" => $result["result"] ? true : false, "device_msg" => $result["device_msg"] @@ -179,16 +200,19 @@ public function reboot_device($device_id) { if ($auth = $this -> require_permission('devices.control')) { return $auth; } $devices_model = new Devices(); + logging() -> info('php:Devices', 'Reboot device attempt', ['device_id' => $device_id]); $result = $devices_model -> reboot_device(intval($device_id)); if(!$result["result"]) { + logging() -> warn('php:Devices', 'Reboot device failed', ['device_id' => $device_id, 'error' => $result["err_alias"] ?? 'unknown']); return $this -> utils() -> response_error( - $result["err_alias"], - [], + $result["err_alias"], + [], [ "device_msg" => $result["msg"] ?? "" ] ); } + logging() -> info('php:Devices', 'Reboot device successful', ['device_id' => $device_id]); return $this -> utils() -> response_success([ "device_msg" => $result["msg"] ]); @@ -204,6 +228,7 @@ return $this -> utils() -> response_error("device_not_found"); } + logging() -> trace('php:Devices', 'Device info fetched', ['device_id' => $device_id]); return $this -> utils() -> response_success([ "device" => $result ]); } @@ -216,6 +241,8 @@ return $this -> utils() -> response_error("device_not_found"); } + logging() -> trace('php:Devices', 'Device fetched', ['device_id' => $device -> id(), 'alias' => $device -> alias]); + $info = [ "id" => $device -> id(), "alias" => $device -> alias, @@ -246,6 +273,8 @@ return $this -> utils() -> response_error("device_not_found"); } + logging() -> trace('php:Devices', 'Device status request', ['device_id' => $device -> id(), 'alias' => $device -> alias]); + $device_status = $device -> device_api() -> get_status(); if(!$device_status || ($device_status["status"] ?? null) !== "ok") { @@ -275,33 +304,41 @@ $device = $devices_model -> by_id(intval($device_id)); if(!$device) { + logging() -> warn('php:Devices', 'Device action failed: not found', ['device_id' => $device_id]); return $this -> utils() -> response_error("device_not_found"); } if(is_string($params)) { $decoded = json_decode($params, true); if(json_last_error() !== JSON_ERROR_NONE) { + logging() -> warn('php:Devices', 'Device action failed: invalid JSON params', ['device_id' => $device_id, 'action' => $action]); return $this -> utils() -> response_error("invalid_json", ["params"]); } $params = $decoded; } if(!is_array($params)) { + logging() -> warn('php:Devices', 'Device action failed: invalid params', ['device_id' => $device_id, 'action' => $action]); return $this -> utils() -> response_error("invalid_params", ["params"]); } if(!preg_match('/^[a-z0-9_]+$/', $action) || strlen($action) > 255) { + logging() -> warn('php:Devices', 'Device action failed: invalid action', ['device_id' => $device_id, 'action' => $action]); return $this -> utils() -> response_error("invalid_action", ["action"]); } + logging() -> info('php:Devices', 'Device action', ['device_id' => $device -> id(), 'alias' => $device -> alias, 'action' => $action]); + $result = $device -> device_api() -> post_action($action, $params); $device_response = $result["data"] ?? []; if(!$device_response) { + logging() -> warn('php:Devices', 'Device action failed: empty response', ['device_id' => $device -> id(), 'action' => $action]); return $this -> utils() -> response_error("device_request_fail"); } if($device_response["status"] != "ok") { + logging() -> warn('php:Devices', 'Device action failed: device error', ['device_id' => $device -> id(), 'action' => $action, 'device_status' => $device_response["status"], 'device_msg' => $device_response["message"] ?? '']); return $this -> utils() -> response_error("device_request_fail", [], [ "device_status" => $device_response["status"], "device_error" => $device_response["status"] ?? "", @@ -309,6 +346,7 @@ ]); } + logging() -> info('php:Devices', 'Device action successful', ['device_id' => $device -> id(), 'alias' => $device -> alias, 'action' => $action]); $response_data = [ "id" => $device -> id(), "alias" => $device -> alias, @@ -331,14 +369,19 @@ $place_area = new Area(intval($place_in_area_id)); if(!$device) { + logging() -> warn('php:Devices', 'Place device in area failed: not found', ['device_id' => $target_id]); return $this -> utils() -> response_error("device_not_found"); } if(!$place_area) { + logging() -> warn('php:Devices', 'Place device in area failed: area not found', ['area_id' => $place_in_area_id]); return $this -> utils() -> response_error("area_not_exists"); } + logging() -> info('php:Devices', 'Place device in area', ['device_id' => $device -> id(), 'alias' => $device -> alias, 'area_id' => $place_area -> id()]); + if(!$device -> place_in_area($place_area)) { + logging() -> warn('php:Devices', 'Place device in area failed', ['device_id' => $device -> id(), 'area_id' => $place_area -> id()]); return $this -> utils() -> response_error("undefined_error"); } @@ -354,9 +397,12 @@ $device = new Device(intval($target_id)); if(!$device) { + logging() -> warn('php:Devices', 'Unassign device from area failed: not found', ['device_id' => $target_id]); return $this -> utils() -> response_error("device_not_found"); } + logging() -> info('php:Devices', 'Unassign device from area', ['device_id' => $device -> id(), 'alias' => $device -> alias]); + return $device -> place_in_area_id(0) ? $this -> utils() -> response_success() : $this -> utils() -> response_error("undefined_error"); @@ -372,6 +418,8 @@ $devices_model = new Devices(); $devices = $devices_model -> get_device_list($status); + logging() -> trace('php:Devices', 'Devices list fetched', ['status' => $status, 'total' => count($devices)]); + return $this -> utils() -> response_success([ "devices" => array_map(function($device) { return $device -> to_array(); @@ -391,6 +439,7 @@ $device = new Device($device_id); if(!$device) { + logging() -> warn('php:Devices', 'Update device name failed: not found', ['device_id' => $device_id]); return $this -> utils() -> response_error("device_not_found"); } @@ -398,7 +447,10 @@ return $this -> utils() -> response_error("empty_field", ["name"]); } + logging() -> info('php:Devices', 'Update device name', ['device_id' => $device -> id(), 'alias' => $device -> alias, 'name' => $name]); + if(!$device -> device_api() -> set_device_name($name)) { + logging() -> warn('php:Devices', 'Update device name failed: device error', ['device_id' => $device_id]); return $this -> utils() -> response_error("device_request_fail"); } @@ -419,9 +471,12 @@ $device = new Device($device_id); if(!$device) { + logging() -> warn('php:Devices', 'Update device description failed: not found', ['device_id' => $device_id]); return $this -> utils() -> response_error("device_not_found"); } + logging() -> info('php:Devices', 'Update device description', ['device_id' => $device -> id(), 'alias' => $device -> alias]); + $device -> description = $description; $device -> update(); @@ -439,19 +494,24 @@ $device = new Device($device_id); if(!$device) { + logging() -> warn('php:Devices', 'Update device alias failed: not found', ['device_id' => $device_id]); return $this -> utils() -> response_error("device_not_found"); } $devices_model = new \SHServ\Models\Devices(); if(!preg_match('/^[a-z0-9_]+$/', $new_alias) || strlen($new_alias) > 255) { + logging() -> warn('php:Devices', 'Update device alias failed: invalid alias', ['device_id' => $device_id, 'new_alias' => $new_alias]); return $this -> utils() -> response_error("invalid_alias", ["new_alias"]); } if(!$devices_model -> alias_is_uniq($new_alias, intval($device_id))) { + logging() -> warn('php:Devices', 'Update device alias failed: already exists', ['device_id' => $device_id, 'new_alias' => $new_alias]); return $this -> utils() -> response_error("alias_already_exists", ["new_alias"]); } + logging() -> info('php:Devices', 'Update device alias', ['device_id' => $device -> id(), 'old_alias' => $device -> alias, 'new_alias' => $new_alias]); + $device -> alias = $new_alias; $device -> update(); @@ -469,17 +529,22 @@ $device = new Device($device_id); if(!$device) { + logging() -> warn('php:Devices', 'Reset device failed: not found', ['device_id' => $device_id]); return $this -> utils() -> response_error("device_not_found"); } + logging() -> warn('php:Devices', 'Reset device', ['device_id' => $device -> id(), 'alias' => $device -> alias]); + $result = $device -> device_api() -> reset(); if(($result["http_code"] ?? 0) !== 200) { + logging() -> warn('php:Devices', 'Reset device failed', ['device_id' => $device_id, 'http_code' => $result["http_code"] ?? 0]); return $this -> utils() -> response_error("device_request_fail", [], [ "device_msg" => $result["error"] ?? "" ]); } + logging() -> info('php:Devices', 'Reset device successful', ['device_id' => $device -> id(), 'alias' => $device -> alias]); return $this -> utils() -> response_success(); } } diff --git a/server/SHServ/Controllers/EventsController.php b/server/SHServ/Controllers/EventsController.php index 6156a19..7c163d9 100644 --- a/server/SHServ/Controllers/EventsController.php +++ b/server/SHServ/Controllers/EventsController.php @@ -19,13 +19,22 @@ $device = $devices_model -> by_hard_id($device_id); if(!$device) { + logging() -> warn('php:Events', 'Event from unknown device', ['device_hard_id' => $device_id, 'event_name' => $event_name]); return $this -> utils() -> response_error("unknown_device", ["device_id"]); } if(!$device -> auth() -> is_active()) { + logging() -> warn('php:Events', 'Event from device with inactive auth', ['device_id' => $device -> id(), 'alias' => $device -> alias, 'event_name' => $event_name]); return $this -> utils() -> response_error("error_of_device_auth"); } + logging() -> info('php:Events', 'Event received', [ + 'device_id' => $device -> id(), + 'alias' => $device -> alias, + 'event_name' => $event_name, + 'channel' => $data["channel"] ?? null, + ]); + $device -> touch_last_contact(); if($device -> connection_status != "active") { diff --git a/server/SHServ/Controllers/ScriptsRESTAPIController.php b/server/SHServ/Controllers/ScriptsRESTAPIController.php index 87fea15..6c4905f 100644 --- a/server/SHServ/Controllers/ScriptsRESTAPIController.php +++ b/server/SHServ/Controllers/ScriptsRESTAPIController.php @@ -23,25 +23,32 @@ if(is_string($params)) { $decoded = json_decode($params, true); if(json_last_error() !== JSON_ERROR_NONE) { + logging() -> warn('php:Scripts', 'Run action script failed: invalid JSON params', ['alias' => $alias]); return $this -> utils() -> response_error("invalid_json", ["params"]); } $params = $decoded; } if(!is_array($params)) { + logging() -> warn('php:Scripts', 'Run action script failed: invalid params', ['alias' => $alias]); return $this -> utils() -> response_error("invalid_params", ["params"]); } if(!preg_match('/^[a-z0-9_]+$/', $alias) || strlen($alias) > 255) { + logging() -> warn('php:Scripts', 'Run action script failed: invalid alias', ['alias' => $alias]); return $this -> utils() -> response_error("invalid_alias", ["alias"]); } + logging() -> info('php:Scripts', 'Run action script', ['alias' => $alias]); + $result = ControlScripts::run_action_script($alias, $params); if(!$result) { + logging() -> warn('php:Scripts', 'Run action script failed: not found or disabled', ['alias' => $alias]); return $this -> utils() -> response_error("action_script_not_found"); } + logging() -> info('php:Scripts', 'Run action script successful', ['alias' => $alias, 'exec_time' => $result['exec_time'] ?? null]); return $this -> utils() -> response_success([ "return" => $result ]); @@ -51,6 +58,8 @@ if ($auth = $this -> require_permission('scripts.view')) { return $auth; } $data = (new Scripts()) -> actions_scripts_list(); + logging() -> trace('php:Scripts', 'Action scripts list fetched', ['total' => count($data)]); + return $this -> utils() -> response_success([ "scripts" => $data, "total" => count($data) @@ -61,6 +70,8 @@ if ($auth = $this -> require_permission('scripts.view')) { return $auth; } $data = (new Scripts()) -> regular_scripts_list(); + logging() -> trace('php:Scripts', 'Regular scripts list fetched', ['total' => count($data)]); + return $this -> utils() -> response_success([ "scripts" => $data, "total" => count($data) @@ -72,6 +83,8 @@ $scripts_model = new Scripts(); $scopes = $scripts_model -> get_scopes_list(); + logging() -> trace('php:Scripts', 'Scope list fetched', ['total' => count($scopes)]); + return $this -> utils() -> response_success([ "scopes" => $scopes, "total" => count($scopes) @@ -103,6 +116,7 @@ public function scope_remove($name) { if ($auth = $this -> require_permission('scripts.edit')) { return $auth; } + logging() -> warn('php:Scripts', 'Remove scope', ['scope_name' => $name]); return (new Scripts()) -> remove_scope($name) ? $this -> utils() -> response_success() : $this -> utils() -> response_error("undefined_error"); @@ -111,6 +125,7 @@ protected function set_script_state(String $type, String $uniq_name, String $state) { if ($auth = $this -> require_permission('scripts.edit')) { return $auth; } if(!in_array($state, ["enable", "disable"], true)) { + logging() -> warn('php:Scripts', 'Set script state failed: invalid state', ['type' => $type, 'alias' => $uniq_name, 'state' => $state]); return $this -> utils() -> response_error("invalid_state", ["state"]); } @@ -120,9 +135,13 @@ $result = (new Scripts()) -> disable_script($type, $uniq_name); } - return $result === true - ? $this -> utils() -> response_success() - : $this -> utils() -> response_error($result); + if ($result === true) { + logging() -> info('php:Scripts', 'Script state changed', ['type' => $type, 'alias' => $uniq_name, 'state' => $state]); + return $this -> utils() -> response_success(); + } + + logging() -> warn('php:Scripts', 'Set script state failed', ['type' => $type, 'alias' => $uniq_name, 'state' => $state, 'error' => $result]); + return $this -> utils() -> response_error($result); } public function set_scope_state($uniq_name, $state) { @@ -151,14 +170,19 @@ $place_area = new Area(intval($place_in_area_id)); if(!$script) { + logging() -> warn('php:Scripts', 'Place script in area failed: not found', ['script_id' => $target_id]); return $this -> utils() -> response_error("script_not_exists"); } if(!$place_area) { + logging() -> warn('php:Scripts', 'Place script in area failed: area not found', ['area_id' => $place_in_area_id]); return $this -> utils() -> response_error("area_not_exists"); } + logging() -> info('php:Scripts', 'Place script in area', ['script_id' => $script -> id(), 'alias' => $script -> alias, 'area_id' => $place_area -> id()]); + if(!$script -> place_in_area($place_area)) { + logging() -> warn('php:Scripts', 'Place script in area failed', ['script_id' => $script -> id(), 'area_id' => $place_area -> id()]); return $this -> utils() -> response_error("undefined_error"); } @@ -174,9 +198,12 @@ $script = new Script(intval($target_id)); if(!$script) { + logging() -> warn('php:Scripts', 'Unassign script from area failed: not found', ['script_id' => $target_id]); return $this -> utils() -> response_error("script_not_exists"); } + logging() -> info('php:Scripts', 'Unassign script from area', ['script_id' => $script -> id(), 'alias' => $script -> alias]); + return $script -> place_in_area_id(0) ? $this -> utils() -> response_success() : $this -> utils() -> response_error("undefined_error"); diff --git a/server/SHServ/Integrations/GAuth/AuthControllerTrait.php b/server/SHServ/Integrations/GAuth/AuthControllerTrait.php index 6a42754..b8b5332 100644 --- a/server/SHServ/Integrations/GAuth/AuthControllerTrait.php +++ b/server/SHServ/Integrations/GAuth/AuthControllerTrait.php @@ -18,6 +18,10 @@ { if (!$this->resolve_user()) { $code = $this->authError ?? 'unauthenticated'; + logging()->warn('php:Auth', 'Unauthenticated access', [ + 'error' => $code, + 'client_ip' => $this->getClientIp(), + ]); return $this->utils()->response_error($code, [], [], 401); } return null; @@ -40,6 +44,11 @@ $resolver = new PermissionResolver(); if (!$resolver->has($user['id'], $user['system_role'], $permissionSlug)) { + logging()->warn('php:Auth', 'Permission denied', [ + 'user_id' => $user['id'], + 'permission' => $permissionSlug, + 'client_ip' => $this->getClientIp(), + ]); return $this->utils()->response_error('permission_denied', [$permissionSlug], [], 403); } @@ -60,13 +69,21 @@ // 1. Session-based auth $sessionUserId = $_SESSION['shserv_user_id'] ?? null; if ($sessionUserId) { - return $this->load_user_by_id((int) $sessionUserId); + $user = $this->load_user_by_id((int) $sessionUserId); + if ($user) { + logging()->debug('php:Auth', 'User resolved via session', ['user_id' => $user['id']]); + } + return $user; } // 2. Bearer token auth $bearer = $this->get_bearer_token(); if ($bearer) { - return $this->resolve_user_by_bearer($bearer); + $user = $this->resolve_user_by_bearer($bearer); + if ($user) { + logging()->debug('php:Auth', 'User resolved via bearer token', ['user_id' => $user['id']]); + } + return $user; } return null; @@ -97,6 +114,7 @@ [['access_token', '=', $token]] ); if (!$result) { + logging()->warn('php:Auth', 'Bearer token not found in DB', ['client_ip' => $this->getClientIp()]); return null; } @@ -104,6 +122,10 @@ if (!empty($row['expires_at'])) { $expiresAt = strtotime((string) $row['expires_at']); if ($expiresAt !== false && time() > $expiresAt) { + logging()->warn('php:Auth', 'Bearer token expired', [ + 'user_id' => (int) $row['user_id'], + 'client_ip' => $this->getClientIp(), + ]); return null; } } diff --git a/server/SHServ/Middleware/ControlScripts.php b/server/SHServ/Middleware/ControlScripts.php index 8ad0699..87b087c 100644 --- a/server/SHServ/Middleware/ControlScripts.php +++ b/server/SHServ/Middleware/ControlScripts.php @@ -133,6 +133,8 @@ return null; } + logging() -> info('php:ControlScripts', 'Run action script', ['alias' => $alias]); + $start_time = microtime(true); $result = self::$actions_scripts[$alias]["script"]($params); @@ -140,6 +142,8 @@ $exec_time = microtime(true) - $start_time; $exec_time = round($exec_time, 3); + logging() -> debug('php:ControlScripts', 'Action script finished', ['alias' => $alias, 'exec_time' => $exec_time]); + return [ "result" => $result, "exec_time" => "{$exec_time} seconds" @@ -156,14 +160,12 @@ return false; } + logging() -> info('php:ControlScripts', 'Run regular script', ['alias' => $alias]); + try { self::$regular_scripts[$alias]["script"](); } catch(\Exception $e) { - \Fury\Kernel\Logging::ins() -> set( - "ControlScripts::run_regular_script", - "Regular script {$alias} failed", - $e -> getMessage() - ); + logging() -> error('php:ControlScripts', 'Regular script failed', ['alias' => $alias, 'message' => $e -> getMessage()]); return false; } diff --git a/server/SHServ/Models/Devices.php b/server/SHServ/Models/Devices.php index 4c51456..6912d0e 100644 --- a/server/SHServ/Models/Devices.php +++ b/server/SHServ/Models/Devices.php @@ -87,11 +87,13 @@ $device -> set_device_token($device_token); $device -> device_api() -> set_device_name($name); + logging() -> info('php:Devices', 'Device created in DB', ['device_id' => $device -> id(), 'alias' => $device -> alias]); return $device; } catch (\Exception $e) { if(app() -> thin_builder -> inTransaction()) { app() -> thin_builder -> rollBack(); } + logging() -> error('php:Devices', 'Device creation failed: DB error', ['alias' => $alias, 'message' => $e -> getMessage()]); return [ "result" => false, "err_alias" => "db_error" @@ -138,6 +140,8 @@ // remove from devices $device -> remove(); + logging() -> info('php:Devices', 'Device removed from DB', ['device_id' => $device_id, 'alias' => $device -> alias]); + return [ "result" => true, "device_msg" => $device_msg @@ -256,6 +260,7 @@ } if($response["data"]["status"] == "ok") { + logging() -> info('php:Devices', 'Device rebooted', ['device_id' => $device_id, 'alias' => $device -> alias]); return [ "result" => true, "msg" => $response["data"]["message"] ?? "" @@ -365,6 +370,8 @@ $device -> touch_last_contact(); } + logging() -> info('php:Devices', 'Scan results reconciled', ['updated' => $updated, 'restored' => $restored]); + return [ "updated" => $updated, "restored" => $restored, diff --git a/server/tests/bootstrap.php b/server/tests/bootstrap.php index 9c276d2..d08a8f5 100644 --- a/server/tests/bootstrap.php +++ b/server/tests/bootstrap.php @@ -63,3 +63,5 @@ 'device_offline_threshold' => 300, ]); } + +\Fury\Kernel\AppContainer::set_logging(new \Fury\Kernel\Logging());