FileFlows icon indicating copy to clipboard operation
FileFlows copied to clipboard

Published 20 hours ago • verified publisher icon revenz

Logging error

Open brianharwell opened this issue 2 years ago • 2 comments

Seeing this error in the logs

REQUEST [POST] [200]: /api/log/message
   at NPoco.ParameterHelper.ProcessParam(String& sql, String rawParam, Object[] args_src, List`1 args_dest, Boolean reuseParameters)
   at NPoco.ParameterHelper.<>c__DisplayClass1_0.<ProcessParams>b__0(Match m)
   at System.Text.RegularExpressions.Regex.<>c.<Replace>b__84_0(ValueTuple`5& state, Match match)
   at System.Text.RegularExpressions.RegexRunner.Scan[TState](Regex regex, String text, Int32 textstart, TState& state, MatchCallback`1 callback, Boolean reuseMatchObject, TimeSpan timeout)
   at System.Text.RegularExpressions.Regex.Run[TState](String input, Int32 startat, TState& state, MatchCallback`1 callback, Boolean reuseMatchObject)
   at System.Text.RegularExpressions.Regex.Replace(MatchEvaluator evaluator, Regex regex, String input, Int32 count, Int32 startat)
   at NPoco.Sql.Build(StringBuilder sb, List`1 args, Sql lhs)
   at NPoco.Sql.Build()
   at NPoco.Database.ExecuteAsync(Sql Sql)
   at FileFlows.Server.Database.Managers.MySqlDbManager.Log(Guid clientUid, LogType type, String message) in /src/Server/Database/Managers/MySqlDbManager.cs:line 135
   at FileFlows.Server.Database.DatabaseLogger.Log(Guid clientUid, LogType type, Object[] args) in /src/Server/Database/DatabaseLogger.cs:line 46
   at FileFlows.Server.Controllers.LogController.Log(LogServiceMessage message) in /src/Server/Controllers/LogController.cs:line 165
   at lambda_method48(Closure , Object )
   at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.AwaitableResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeActionMethodAsync>g__Awaited|12_0(ControllerActionInvoker invoker, ValueTask`1 actionResultValueTask)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeNextActionFilterAsync>g__Awaited|10_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeInnerFilterAsync()
--- End of stack trace from previous location ---
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeNextResourceFilter>g__Awaited|25_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Rethrow(ResourceExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.InvokeFilterPipelineAsync()
--- End of stack trace from previous location ---
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Awaited|17_0(ResourceInvoker invoker, Task task, IDisposable scope)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Awaited|17_0(ResourceInvoker invoker, Task task, IDisposable scope)
   at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger)
   at FileFlows.Server.Middleware.LoggingMiddleware.Invoke(HttpContext context) in /src/Server/Middleware/LoggingMiddleware.cs:line 53
   at FileFlows.Server.Middleware.ExceptionMiddleware.Invoke(HttpContext context) in /src/Server/Middleware/ExceptionMiddleware.cs:line 40

brianharwell avatar Sep 14 '22 18:09 brianharwell

v1.0.3 will add some more logging to try figure this out. something with what its trying to insert int the db, but without the insert statement cant do much. v1.0.3 will log the command its trying to insert insert.... just hope that doesn't do a stack overflow....

revenz avatar Sep 15 '22 07:09 revenz

This is a few lines before the error...

2022-09-14 14:22:44.166 [ERRR] -> ExceptionMiddleware: Specified argument was out of the range of valid values. (Parameter 'Parameter '@0' specified but only 0 parameters supplied (in `insert into DbLogMessage (ClientUid, LogDate, Type, Message) values ('00000000-0000-0000-0000-000000000000', '2022-09-14 14:22:35.029', 3, 'Getting directory size (TEMP DIR) \'/temp\': 209.38 MB'),
('00000000-0000-0000-0000-000000000000', '2022-09-14 14:22:35.029', 3, 'Getting node \'32eec574-c278-4ca2-8c06-10f6e968f694\' size (TEMP DIR) \'/app/Temp\': 0 B'),
('00000000-0000-0000-0000-000000000000', '2022-09-14 14:22:35.032', 3, 'Getting directory size (LOGGING DIR) \'/app/Logs\': 53.63 MB'),
('00000000-0000-0000-0000-000000000000', '2022-09-14 14:22:35.032', 3, 'Getting node \'32eec574-c278-4ca2-8c06-10f6e968f694\' size (LOGGING DIR) \'/app/Logs\': 6.51 MB'),
('00000000-0000-0000-0000-000000000000', '2022-09-14 14:22:35.279', 2, 'Triggering worker: FlowWorker'),
('00000000-0000-0000-0000-000000000000', '2022-09-14 14:22:35.279', 2, 'Making request [GET]: http://localhost:5000/api/settings/current-config/revision'),
('00000000-0000-0000-0000-000000000000', '2022-09-14 14:22:35.363', 3, 'Node \'Internal Processing Node\' is not enabled'),
('00000000-0000-0000-0000-000000000000', '2022-09-14 14:22:37.270', 2, 'Took \'00:00:00.0026112\' to fetch: select case when LibraryFile.Status > 0 then LibraryFile.Status when LibraryFile.Status = 0 and LibraryUid IN (\'6d1fa297-524b-4f5e-b931-22bff42ab952\') then -2 when HoldUntil > now() then -3 else LibraryFile.Status end as FileStatus, count(Uid) as Count from LibraryFile group by FileStatus'),
('00000000-0000-0000-0000-000000000000', '2022-09-14 14:22:37.374', 2, 'Processing Timer Queue: Plex Movies 2 - Subtitles'),
('00000000-0000-0000-0000-000000000000', '2022-09-14 14:22:40.667', 2, 'Took \'00:00:00.0066448\' to get: select * from LibraryFile where Name = @0 or OutputPath = @0'),
('00000000-0000-0000-0000-000000000000', '2022-09-14 14:22:43.163', 2, 'Triggering worker: FlowRunnerMonitor'),
('32eec574-c278-4ca2-8c06-10f6e968f694', '2022-09-14 14:22:43.500', 2, 'Triggering worker: FlowWorker'),
('32eec574-c278-4ca2-8c06-10f6e968f694', '2022-09-14 14:22:43.500', 2, 'Making request [GET]: http://192.168.1.226:5000/api/node/by-address/fileflows-node?version=1.0.3.1967'),
('32eec574-c278-4ca2-8c06-10f6e968f694', '2022-09-14 14:22:43.642', 2, 'Making request [GET]: http://192.168.1.226:5000/api/system/version'),
('32eec574-c278-4ca2-8c06-10f6e968f694', '2022-09-14 14:22:43.685', 2, 'Making request [GET]: http://192.168.1.226:5000/api/node/by-address/fileflows-node?version=1.0.3.1967'),
('32eec574-c278-4ca2-8c06-10f6e968f694', '2022-09-14 14:22:43.718', 2, 'Making request [POST]: http://192.168.1.226:5000/api/system/node-system-statistics'),
('32eec574-c278-4ca2-8c06-10f6e968f694', '2022-09-14 14:22:43.718', 2, 'Triggering worker: SystemStatisticsWorker'),
('32eec574-c278-4ca2-8c06-10f6e968f694', '2022-09-14 14:22:43.718', 3, 'Directory \'/app/Temp size: 0 B'),
('32eec574-c278-4ca2-8c06-10f6e968f694', '2022-09-14 14:22:43.718', 3, 'Directory \'/app/Logs size: 6.51 MB'),
('32eec574-c278-4ca2-8c06-10f6e968f694', '2022-09-14 14:22:43.821', 2, 'Making request [GET]: http://192.168.1.226:5000/api/settings/current-config/revision'),
('32eec574-c278-4ca2-8c06-10f6e968f694', '2022-09-14 14:22:44.072', 2, 'Making request [GET]: http://192.168.1.226:5000/api/settings/fileflows-status')`)')
REQUEST [POST] [200]: /api/log/message

brianharwell avatar Sep 15 '22 13:09 brianharwell

is this still an issue in 1.0.5?

revenz avatar Oct 04 '22 07:10 revenz

I'm not seeing any more errors with logging on 1.0.5.

brianharwell avatar Oct 04 '22 14:10 brianharwell