diff options
author | vvvv <[email protected]> | 2025-03-19 13:47:50 +0300 |
---|---|---|
committer | vvvv <[email protected]> | 2025-03-19 14:07:15 +0300 |
commit | bd190ddaaab2a259b50caebe3cb8d6666c90eacc (patch) | |
tree | 83d7db05a732be28dee1fb2760bbcaeef907f539 | |
parent | 61b92aeb846ebc6180fb4c18c85ff10c58093610 (diff) |
YQL-19724 logger for udf resolving
commit_hash:c019511f90871e0a4d783856db0fa2272e21a336
31 files changed, 228 insertions, 59 deletions
diff --git a/yql/essentials/core/issue/protos/issue_id.proto b/yql/essentials/core/issue/protos/issue_id.proto index b8ae30b8f4a..df65b98083e 100644 --- a/yql/essentials/core/issue/protos/issue_id.proto +++ b/yql/essentials/core/issue/protos/issue_id.proto @@ -42,6 +42,7 @@ message TIssuesIds { // core informational CORE_TOP_UNSUPPORTED_BLOCK_TYPES = 1200; CORE_TOP_UNSUPPORTED_BLOCK_CALLABLES = 1201; + CORE_UDF_RESOLVER = 1202; // core errors CORE_GC_NODES_LIMIT_EXCEEDED = 1500; diff --git a/yql/essentials/core/issue/yql_issue.txt b/yql/essentials/core/issue/yql_issue.txt index c5be249510f..251d757b246 100644 --- a/yql/essentials/core/issue/yql_issue.txt +++ b/yql/essentials/core/issue/yql_issue.txt @@ -688,6 +688,10 @@ ids { severity: S_INFO } ids { + code: CORE_UDF_RESOLVER + severity: S_INFO +} +ids { code: CBO_ENUM_LIMIT_REACHED severity: S_WARNING } diff --git a/yql/essentials/core/qplayer/udf_resolver/yql_qplayer_udf_resolver.cpp b/yql/essentials/core/qplayer/udf_resolver/yql_qplayer_udf_resolver.cpp index 15cc73400ae..c80fe494c6a 100644 --- a/yql/essentials/core/qplayer/udf_resolver/yql_qplayer_udf_resolver.cpp +++ b/yql/essentials/core/qplayer/udf_resolver/yql_qplayer_udf_resolver.cpp @@ -38,7 +38,7 @@ public: } bool LoadMetadata(const TVector<TImport*>& imports, - const TVector<TFunction*>& functions, TExprContext& ctx) const final { + const TVector<TFunction*>& functions, TExprContext& ctx, NUdf::ELogLevel logLevel) const final { if (QContext_.CanRead()) { for (auto& f : functions) { auto key = MakeKey(f); @@ -53,7 +53,7 @@ public: return true; } - auto res = Inner_->LoadMetadata(imports, functions, ctx); + auto res = Inner_->LoadMetadata(imports, functions, ctx, logLevel); if (res && QContext_.CanWrite()) { // calculate hash for each function and store it for (const auto& f : functions) { @@ -66,12 +66,12 @@ public: return res; } - TResolveResult LoadRichMetadata(const TVector<TImport>& imports) const final { + TResolveResult LoadRichMetadata(const TVector<TImport>& imports, NUdf::ELogLevel logLevel) const final { if (QContext_.CanRead()) { ythrow yexception() << "Can't replay LoadRichMetadata"; } - return Inner_->LoadRichMetadata(imports); + return Inner_->LoadRichMetadata(imports, logLevel); } bool ContainsModule(const TStringBuf& moduleName) const final { @@ -127,6 +127,15 @@ private: node("IsStrict", NYT::TNode(true)); } + if (!f->Messages.empty()) { + auto list = NYT::TNode::CreateList(); + for (const auto& x : f->Messages) { + list.Add(x); + } + + node("Messages", list); + } + return NYT::NodeToYsonString(node,NYT::NYson::EYsonFormat::Binary); } @@ -154,6 +163,12 @@ private: if (node.HasKey("IsStrict")) { f->IsStrict = node["IsStrict"].AsBool(); } + + if (node.HasKey("Messages")) { + for (const auto& x : node["Messages"].AsList()) { + f->Messages.push_back(x.AsString()); + } + } } private: diff --git a/yql/essentials/core/type_ann/type_ann_core.cpp b/yql/essentials/core/type_ann/type_ann_core.cpp index b42df0c2656..665378e19f0 100644 --- a/yql/essentials/core/type_ann/type_ann_core.cpp +++ b/yql/essentials/core/type_ann/type_ann_core.cpp @@ -486,7 +486,7 @@ namespace NTypeAnnImpl { imports.push_back(&x.second); } - if (!Types.UdfResolver->LoadMetadata(imports, functions, Expr)) { + if (!Types.UdfResolver->LoadMetadata(imports, functions, Expr, Types.RuntimeLogLevel)) { return false; } @@ -7661,7 +7661,15 @@ template <NKikimr::NUdf::EDataSlot DataSlot> return MakeIntrusive<TIssue>(ctx.Expr.GetPosition(input->Pos()), TStringBuilder() << "At " << input->Head().Content()); }); - if (!ctx.LoadUdfMetadata(functions)) { + auto success = ctx.LoadUdfMetadata(functions); + for (const auto& m : description.Messages) { + TIssue issue; + issue.SetMessage(m); + issue.SetCode(TIssuesIds::CORE_UDF_RESOLVER, TSeverityIds::S_INFO); + ctx.Expr.AddError(issue); + } + + if (!success) { return IGraphTransformer::TStatus::Error; } diff --git a/yql/essentials/core/yql_udf_index.cpp b/yql/essentials/core/yql_udf_index.cpp index 7f2053693e0..4779770550e 100644 --- a/yql/essentials/core/yql_udf_index.cpp +++ b/yql/essentials/core/yql_udf_index.cpp @@ -49,6 +49,10 @@ TVector<TResourceInfo::TPtr> ConvertResolveResultToResources(const TResolveResul newFunction.SupportsBlocks = udf.GetSupportsBlocks(); } + for (const auto& m : udf.GetMessages()) { + newFunction.Messages.push_back(m); + } + functionIndex[package].push_back(newFunction); } @@ -286,25 +290,25 @@ void TUdfIndex::RegisterResources(const TVector<TResourceInfo::TPtr>& resources, } } -void LoadRichMetadataToUdfIndex(const IUdfResolver& resolver, const TVector<TString>& paths, bool isTrusted, TUdfIndex::EOverrideMode mode, TUdfIndex& registry) { +void LoadRichMetadataToUdfIndex(const IUdfResolver& resolver, const TVector<TString>& paths, bool isTrusted, TUdfIndex::EOverrideMode mode, TUdfIndex& registry, NUdf::ELogLevel logLevel) { TMap<TString, TString> pathsWithMd5; for (const auto& path : paths) { pathsWithMd5[path] = ""; } - LoadRichMetadataToUdfIndex(resolver, pathsWithMd5, isTrusted, mode, registry); + LoadRichMetadataToUdfIndex(resolver, pathsWithMd5, isTrusted, mode, registry, logLevel); } -void LoadRichMetadataToUdfIndex(const IUdfResolver& resolver, const TMap<TString, TString>& pathsWithMd5, bool isTrusted, TUdfIndex::EOverrideMode mode, TUdfIndex& registry) { +void LoadRichMetadataToUdfIndex(const IUdfResolver& resolver, const TMap<TString, TString>& pathsWithMd5, bool isTrusted, TUdfIndex::EOverrideMode mode, TUdfIndex& registry, NUdf::ELogLevel logLevel) { TVector<TString> paths; paths.reserve(pathsWithMd5.size()); for (const auto& p : pathsWithMd5) { paths.push_back(p.first); } - const TResolveResult resolveResult = LoadRichMetadata(resolver, paths); + const TResolveResult resolveResult = LoadRichMetadata(resolver, paths, logLevel); AddResolveResultToRegistry(resolveResult, pathsWithMd5, isTrusted, mode, registry); } -void LoadRichMetadataToUdfIndex(const IUdfResolver& resolver, const TVector<TUserDataBlock>& blocks, bool isTrusted, TUdfIndex::EOverrideMode mode, TUdfIndex& registry) { +void LoadRichMetadataToUdfIndex(const IUdfResolver& resolver, const TVector<TUserDataBlock>& blocks, bool isTrusted, TUdfIndex::EOverrideMode mode, TUdfIndex& registry, NUdf::ELogLevel logLevel) { TVector<TUserDataBlock> blocksResolve; blocksResolve.reserve(blocks.size()); // we can work with file path only @@ -340,14 +344,14 @@ void LoadRichMetadataToUdfIndex(const IUdfResolver& resolver, const TVector<TUse br.CustomUdfPrefix = b.CustomUdfPrefix; blocksResolve.emplace_back(br); } - const TResolveResult resolveResult = LoadRichMetadata(resolver, blocksResolve); + const TResolveResult resolveResult = LoadRichMetadata(resolver, blocksResolve, logLevel); AddResolveResultToRegistry(resolveResult, pathsWithMd5, isTrusted, mode, registry); } -void LoadRichMetadataToUdfIndex(const IUdfResolver& resolver, const TUserDataBlock& block, TUdfIndex::EOverrideMode mode, TUdfIndex& registry) { +void LoadRichMetadataToUdfIndex(const IUdfResolver& resolver, const TUserDataBlock& block, TUdfIndex::EOverrideMode mode, TUdfIndex& registry, NUdf::ELogLevel logLevel) { TVector<TUserDataBlock> blocks({ block }); const bool isTrusted = false; - LoadRichMetadataToUdfIndex(resolver, blocks, isTrusted, mode, registry); + LoadRichMetadataToUdfIndex(resolver, blocks, isTrusted, mode, registry, logLevel); } } // namespace NYql diff --git a/yql/essentials/core/yql_udf_index.h b/yql/essentials/core/yql_udf_index.h index 1ac882bd81e..2b6a7fdea6f 100644 --- a/yql/essentials/core/yql_udf_index.h +++ b/yql/essentials/core/yql_udf_index.h @@ -19,6 +19,7 @@ struct TFunctionInfo { TString RunConfigType; bool IsStrict = false; bool SupportsBlocks = false; + TVector<TString> Messages; }; // todo: specify whether path is frozen @@ -138,9 +139,9 @@ private: TMap<TString, TSet<TString>> ICaseModules_; }; -void LoadRichMetadataToUdfIndex(const IUdfResolver& resolver, const TVector<TString>& paths, bool isTrusted, TUdfIndex::EOverrideMode mode, TUdfIndex& registry); -void LoadRichMetadataToUdfIndex(const IUdfResolver& resolver, const TMap<TString, TString>& pathsWithMd5, bool isTrusted, TUdfIndex::EOverrideMode mode, TUdfIndex& registry); -void LoadRichMetadataToUdfIndex(const IUdfResolver& resolver, const TVector<TUserDataBlock>& blocks, TUdfIndex::EOverrideMode mode, TUdfIndex& registry); -void LoadRichMetadataToUdfIndex(const IUdfResolver& resolver, const TUserDataBlock& block, TUdfIndex::EOverrideMode mode, TUdfIndex& registry); +void LoadRichMetadataToUdfIndex(const IUdfResolver& resolver, const TVector<TString>& paths, bool isTrusted, TUdfIndex::EOverrideMode mode, TUdfIndex& registry, NUdf::ELogLevel logLevel = NUdf::ELogLevel::Info); +void LoadRichMetadataToUdfIndex(const IUdfResolver& resolver, const TMap<TString, TString>& pathsWithMd5, bool isTrusted, TUdfIndex::EOverrideMode mode, TUdfIndex& registry, NUdf::ELogLevel logLevel = NUdf::ELogLevel::Info); +void LoadRichMetadataToUdfIndex(const IUdfResolver& resolver, const TVector<TUserDataBlock>& blocks, TUdfIndex::EOverrideMode mode, TUdfIndex& registry, NUdf::ELogLevel logLevel = NUdf::ELogLevel::Info); +void LoadRichMetadataToUdfIndex(const IUdfResolver& resolver, const TUserDataBlock& block, TUdfIndex::EOverrideMode mode, TUdfIndex& registry, NUdf::ELogLevel logLevel = NUdf::ELogLevel::Info); } diff --git a/yql/essentials/core/yql_udf_resolver.cpp b/yql/essentials/core/yql_udf_resolver.cpp index b4d29015cd8..c0742dde474 100644 --- a/yql/essentials/core/yql_udf_resolver.cpp +++ b/yql/essentials/core/yql_udf_resolver.cpp @@ -2,7 +2,7 @@ namespace NYql { -TResolveResult LoadRichMetadata(const IUdfResolver& resolver, const TVector<TUserDataBlock>& blocks) { +TResolveResult LoadRichMetadata(const IUdfResolver& resolver, const TVector<TUserDataBlock>& blocks, NUdf::ELogLevel logLevel) { TVector<IUdfResolver::TImport> imports; imports.reserve(blocks.size()); std::transform(blocks.begin(), blocks.end(), std::back_inserter(imports), [](auto& b) { @@ -13,10 +13,10 @@ TResolveResult LoadRichMetadata(const IUdfResolver& resolver, const TVector<TUse return import; }); - return resolver.LoadRichMetadata(imports); + return resolver.LoadRichMetadata(imports, logLevel); } -TResolveResult LoadRichMetadata(const IUdfResolver& resolver, const TVector<TString>& paths) { +TResolveResult LoadRichMetadata(const IUdfResolver& resolver, const TVector<TString>& paths, NUdf::ELogLevel logLevel) { TVector<TUserDataBlock> blocks; blocks.reserve(paths.size()); std::transform(paths.begin(), paths.end(), std::back_inserter(blocks), [](auto& p) { @@ -27,7 +27,7 @@ TResolveResult LoadRichMetadata(const IUdfResolver& resolver, const TVector<TStr return b; }); - return LoadRichMetadata(resolver, blocks); + return LoadRichMetadata(resolver, blocks, logLevel); } } diff --git a/yql/essentials/core/yql_udf_resolver.h b/yql/essentials/core/yql_udf_resolver.h index 9b6bf4f8eec..ade582f822e 100644 --- a/yql/essentials/core/yql_udf_resolver.h +++ b/yql/essentials/core/yql_udf_resolver.h @@ -4,6 +4,7 @@ #include <yql/essentials/providers/common/proto/udf_resolver.pb.h> #include <yql/essentials/public/issue/yql_issue.h> +#include <yql/essentials/public/udf/udf_log.h> #include <util/generic/maybe.h> #include <util/generic/vector.h> @@ -48,6 +49,7 @@ public: const TTypeAnnotationNode* CallableType = nullptr; bool SupportsBlocks = false; bool IsStrict = false; + TVector<TString> Messages; }; struct TImport { @@ -66,13 +68,13 @@ public: */ virtual TMaybe<TFilePathWithMd5> GetSystemModulePath(const TStringBuf& moduleName) const = 0; virtual bool LoadMetadata(const TVector<TImport*>& imports, - const TVector<TFunction*>& functions, TExprContext& ctx) const = 0; + const TVector<TFunction*>& functions, TExprContext& ctx, NUdf::ELogLevel logLevel) const = 0; - virtual TResolveResult LoadRichMetadata(const TVector<TImport>& imports) const = 0; + virtual TResolveResult LoadRichMetadata(const TVector<TImport>& imports, NUdf::ELogLevel logLevel) const = 0; virtual bool ContainsModule(const TStringBuf& moduleName) const = 0; }; -TResolveResult LoadRichMetadata(const IUdfResolver& resolver, const TVector<TUserDataBlock>& blocks); -TResolveResult LoadRichMetadata(const IUdfResolver& resolver, const TVector<TString>& paths); +TResolveResult LoadRichMetadata(const IUdfResolver& resolver, const TVector<TUserDataBlock>& blocks, NUdf::ELogLevel logLevel = NUdf::ELogLevel::Info); +TResolveResult LoadRichMetadata(const IUdfResolver& resolver, const TVector<TString>& paths, NUdf::ELogLevel logLevel = NUdf::ELogLevel::Info); } diff --git a/yql/essentials/core/yql_user_data_storage.cpp b/yql/essentials/core/yql_user_data_storage.cpp index 269e3238cdb..1893067a574 100644 --- a/yql/essentials/core/yql_user_data_storage.cpp +++ b/yql/essentials/core/yql_user_data_storage.cpp @@ -224,7 +224,8 @@ TUserDataBlock* TUserDataStorage::FreezeNoThrow(const TUserDataKey& key, TString } TUserDataBlock* TUserDataStorage::FreezeUdfNoThrow(const TUserDataKey& key, - TString& errorMessage,const TString& customUdfPrefix) { + TString& errorMessage,const TString& customUdfPrefix, + NUdf::ELogLevel logLevel) { TUserDataBlock* block = FreezeNoThrow(key, errorMessage); if (!block) { return nullptr; @@ -245,7 +246,7 @@ TUserDataBlock* TUserDataStorage::FreezeUdfNoThrow(const TUserDataKey& key, YQL_PROFILE_SCOPE(DEBUG, scope.c_str()); Y_ENSURE(UdfResolver_); Y_ENSURE(UdfIndex_); - LoadRichMetadataToUdfIndex(*UdfResolver_, *block, TUdfIndex::EOverrideMode::ReplaceWithNew, *UdfIndex_); + LoadRichMetadataToUdfIndex(*UdfResolver_, *block, TUdfIndex::EOverrideMode::ReplaceWithNew, *UdfIndex_, logLevel); } catch (const std::exception& e) { errorMessage = TStringBuilder() << "Failed to scan udf with key " << key << ", details: " << e.what(); return nullptr; diff --git a/yql/essentials/core/yql_user_data_storage.h b/yql/essentials/core/yql_user_data_storage.h index c8c556426ee..70abdf83729 100644 --- a/yql/essentials/core/yql_user_data_storage.h +++ b/yql/essentials/core/yql_user_data_storage.h @@ -61,7 +61,7 @@ public: TUserDataBlock* FreezeNoThrow(const TUserDataKey& key, TString& errorMessage); // as above + udf will be scanned and meta info put into UdfIndex - TUserDataBlock* FreezeUdfNoThrow(const TUserDataKey& key, TString& errorMessage, const TString& customUdfPrefix = {}); + TUserDataBlock* FreezeUdfNoThrow(const TUserDataKey& key, TString& errorMessage, const TString& customUdfPrefix, NUdf::ELogLevel logLevel); // returns function which will register value in cache after invocation NThreading::TFuture<std::function<TUserDataBlock()>> FreezeAsync(const TUserDataKey& key); diff --git a/yql/essentials/providers/common/proto/udf_resolver.proto b/yql/essentials/providers/common/proto/udf_resolver.proto index 8b678157264..8693e9de4e5 100644 --- a/yql/essentials/providers/common/proto/udf_resolver.proto +++ b/yql/essentials/providers/common/proto/udf_resolver.proto @@ -29,6 +29,7 @@ message TFunctionResult { optional string ReturnDoc = 13; optional bool SupportsBlocks = 14; optional bool IsStrict = 15; + repeated string Messages = 16; }; message TImport { @@ -50,6 +51,7 @@ message TImportResult { message TResolve { repeated TImport Imports = 1; repeated TFunction Udfs = 2; + optional uint32 RuntimeLogLevel = 3; }; message TResolveResult { diff --git a/yql/essentials/providers/common/udf_resolve/yql_outproc_udf_resolver.cpp b/yql/essentials/providers/common/udf_resolve/yql_outproc_udf_resolver.cpp index 9e13ad766b3..778dfc16388 100644 --- a/yql/essentials/providers/common/udf_resolve/yql_outproc_udf_resolver.cpp +++ b/yql/essentials/providers/common/udf_resolve/yql_outproc_udf_resolver.cpp @@ -139,7 +139,7 @@ public: return FunctionRegistry_->IsLoadedUdfModule(moduleName); } - bool LoadMetadata(const TVector<TImport*>& imports, const TVector<TFunction*>& functions, TExprContext& ctx) const override { + bool LoadMetadata(const TVector<TImport*>& imports, const TVector<TFunction*>& functions, TExprContext& ctx, NUdf::ELogLevel logLevel) const override { THashSet<TString> requiredLoadedModules; THashSet<TString> requiredExternalModules; TVector<TFunction*> loadedFunctions; @@ -164,6 +164,7 @@ public: } TResolve request; + request.SetRuntimeLogLevel(static_cast<ui32>(logLevel)); TVector<TImport*> usedImports; THoldingFileStorage holdingFileStorage(FileStorage_); THolder<TFilesBox> filesBox = CreateFilesBoxOverFileStorageTemp(); @@ -232,7 +233,7 @@ public: // extract regardless of hasErrors value hasErrors = !ExtractMetadata(response, usedImports, externalFunctions, ctx) || hasErrors; - hasErrors = !LoadFunctionsMetadata(loadedFunctions, *FunctionRegistry_, TypeInfoHelper_, ctx) || hasErrors; + hasErrors = !LoadFunctionsMetadata(loadedFunctions, *FunctionRegistry_, TypeInfoHelper_, ctx, logLevel) || hasErrors; if (!hasErrors) { for (auto& m : FunctionRegistry_->GetAllModuleNames()) { @@ -246,8 +247,9 @@ public: return !hasErrors; } - TResolveResult LoadRichMetadata(const TVector<TImport>& imports) const override { + TResolveResult LoadRichMetadata(const TVector<TImport>& imports, NUdf::ELogLevel logLevel) const override { TResolve request; + request.SetRuntimeLogLevel(static_cast<ui32>(logLevel)); THoldingFileStorage holdingFileStorage(FileStorage_); THolder<TFilesBox> filesBox = CreateFilesBoxOverFileStorageTemp(); Y_DEFER { @@ -369,6 +371,9 @@ private: } udf->SupportsBlocks = udfRes.GetSupportsBlocks(); udf->IsStrict = udfRes.GetIsStrict(); + for (const auto& m : udfRes.GetMessages()) { + udf->Messages.push_back(m); + } } } diff --git a/yql/essentials/providers/common/udf_resolve/yql_simple_udf_resolver.cpp b/yql/essentials/providers/common/udf_resolve/yql_simple_udf_resolver.cpp index ab1ab1b2375..9ec1aa2b52c 100644 --- a/yql/essentials/providers/common/udf_resolve/yql_simple_udf_resolver.cpp +++ b/yql/essentials/providers/common/udf_resolve/yql_simple_udf_resolver.cpp @@ -9,6 +9,8 @@ #include <yql/essentials/minikql/mkql_utils.h> #include <yql/essentials/minikql/computation/mkql_computation_node.h> +#include <yql/essentials/utils/time_provider.h> + #include <library/cpp/digest/md5/md5.h> #include <util/generic/vector.h> @@ -49,7 +51,7 @@ public: } bool LoadMetadata(const TVector<TImport*>& imports, - const TVector<TFunction*>& functions, TExprContext& ctx) const override { + const TVector<TFunction*>& functions, TExprContext& ctx, NUdf::ELogLevel logLevel) const override { with_lock(Lock_) { bool hasErrors = false; @@ -134,13 +136,14 @@ public: } } - hasErrors = !LoadFunctionsMetadata(functions, *newRegistry, TypeInfoHelper_, ctx) || hasErrors; + hasErrors = !LoadFunctionsMetadata(functions, *newRegistry, TypeInfoHelper_, ctx, logLevel) || hasErrors; return !hasErrors; } } - TResolveResult LoadRichMetadata(const TVector<TImport>& imports) const override { + TResolveResult LoadRichMetadata(const TVector<TImport>& imports, NUdf::ELogLevel logLevel) const override { Y_UNUSED(imports); + Y_UNUSED(logLevel); ythrow yexception() << "LoadRichMetadata is not supported in SimpleUdfResolver"; } @@ -167,7 +170,7 @@ IUdfResolver::TPtr CreateSimpleUdfResolver( bool LoadFunctionsMetadata(const TVector<IUdfResolver::TFunction*>& functions, const NKikimr::NMiniKQL::IFunctionRegistry& functionRegistry, NUdf::ITypeInfoHelper::TPtr typeInfoHelper, - TExprContext& ctx) { + TExprContext& ctx, NUdf::ELogLevel logLevel) { bool hasErrors = false; TScopedAlloc alloc(__LOCATION__); @@ -202,10 +205,16 @@ bool LoadFunctionsMetadata(const TVector<IUdfResolver::TFunction*>& functions, auto secureParamsProvider = MakeSimpleSecureParamsProvider(udf.SecureParams); + auto logProvider = NUdf::MakeLogProvider( + [&](const NUdf::TStringRef& component, NUdf::ELogLevel level, const NUdf::TStringRef& message) { + udf.Messages.push_back(TStringBuilder() << GetTimeProvider()->Now() << " " << component << " [" << level << "] " << message); + }, + logLevel); + TFunctionTypeInfo funcInfo; auto status = functionRegistry.FindFunctionTypeInfo(env, typeInfoHelper, nullptr, udf.Name, mkqlUserType, udf.TypeConfig, NUdf::IUdfModule::TFlags::TypesOnly, {}, secureParamsProvider.get(), - nullptr, &funcInfo); + logProvider.Get(), &funcInfo); if (!status.IsOk()) { ctx.AddError(TIssue(udf.Pos, TStringBuilder() << "Failed to find UDF function: " << udf.Name << ", reason: " << status.GetError())); diff --git a/yql/essentials/providers/common/udf_resolve/yql_simple_udf_resolver.h b/yql/essentials/providers/common/udf_resolve/yql_simple_udf_resolver.h index 87b40e97b52..171eee981fd 100644 --- a/yql/essentials/providers/common/udf_resolve/yql_simple_udf_resolver.h +++ b/yql/essentials/providers/common/udf_resolve/yql_simple_udf_resolver.h @@ -16,7 +16,7 @@ IUdfResolver::TPtr CreateSimpleUdfResolver( bool LoadFunctionsMetadata(const TVector<IUdfResolver::TFunction*>& functions, const NKikimr::NMiniKQL::IFunctionRegistry& functionRegistry, NUdf::ITypeInfoHelper::TPtr typeInfoHelper, - TExprContext& ctx); + TExprContext& ctx, NUdf::ELogLevel logLevel); } // namespace NCommon } // namespace NYql diff --git a/yql/essentials/providers/common/udf_resolve/yql_udf_resolver_with_index.cpp b/yql/essentials/providers/common/udf_resolve/yql_udf_resolver_with_index.cpp index 097135ae7d4..689962c4e2e 100644 --- a/yql/essentials/providers/common/udf_resolve/yql_udf_resolver_with_index.cpp +++ b/yql/essentials/providers/common/udf_resolve/yql_udf_resolver_with_index.cpp @@ -78,7 +78,8 @@ public: } } - bool LoadMetadata(const TVector<TImport*>& imports, const TVector<TFunction*>& functions, TExprContext& ctx) const override { + bool LoadMetadata(const TVector<TImport*>& imports, const TVector<TFunction*>& functions, + TExprContext& ctx, NUdf::ELogLevel logLevel) const override { with_lock(Lock_) { bool hasErrors = false; THashSet<TString> requiredModules; @@ -105,12 +106,12 @@ public: fallbackImports.insert(fallbackImports.end(), additionalImports.begin(), additionalImports.end()); - return Fallback_->LoadMetadata(fallbackImports, fallbackFunctions, ctx) && !hasErrors; + return Fallback_->LoadMetadata(fallbackImports, fallbackFunctions, ctx, logLevel) && !hasErrors; } } - TResolveResult LoadRichMetadata(const TVector<TImport>& imports) const override { - return Fallback_->LoadRichMetadata(imports); + TResolveResult LoadRichMetadata(const TVector<TImport>& imports, NUdf::ELogLevel logLevel) const override { + return Fallback_->LoadRichMetadata(imports, logLevel); } bool ContainsModule(const TStringBuf& moduleName) const override { @@ -203,6 +204,7 @@ private: function.NormalizedUserType = std::get<0>(ctx.SingletonTypeCache); function.IsStrict = info.IsStrict; function.SupportsBlocks = info.SupportsBlocks; + function.Messages = info.Messages; return true; } diff --git a/yql/essentials/providers/config/yql_config_provider.cpp b/yql/essentials/providers/config/yql_config_provider.cpp index 444fdda1d31..94b2b7ec25e 100644 --- a/yql/essentials/providers/config/yql_config_provider.cpp +++ b/yql/essentials/providers/config/yql_config_provider.cpp @@ -1082,7 +1082,7 @@ namespace { TString errorMessage; const TUserDataBlock* udfSource = nullptr; if (!Types.QContext.CanRead()) { - udfSource = Types.UserDataStorage->FreezeUdfNoThrow(key, errorMessage, customUdfPrefix); + udfSource = Types.UserDataStorage->FreezeUdfNoThrow(key, errorMessage, customUdfPrefix, Types.RuntimeLogLevel); if (!udfSource) { ctx.AddError(TIssue(pos, TStringBuilder() << "Unknown file: " << fileAlias << ", details: " << errorMessage)); return false; diff --git a/yql/essentials/public/udf/udf_log.cpp b/yql/essentials/public/udf/udf_log.cpp index 640ebac9140..d9f1327acb2 100644 --- a/yql/essentials/public/udf/udf_log.cpp +++ b/yql/essentials/public/udf/udf_log.cpp @@ -2,6 +2,7 @@ #include <util/system/mutex.h> #include <util/generic/hash.h> #include <util/generic/maybe.h> +#include <util/string/join.h> namespace NYql { namespace NUdf { @@ -183,6 +184,15 @@ TMaybe<ELogLevel> TryLevelFromString(TStringBuf str) { return Nothing(); } +#define ENUM_STR_JOIN(name, val) \ + #name, + +TString LogLevelAvailables() { + return JoinSeq(", ", + {UDF_LOG_LEVEL(ENUM_STR_JOIN)} + ); +} + TUniquePtr<ILogProvider> MakeLogProvider(TLogProviderFunc func, TMaybe<ELogLevel> filter) { return new TLogProvider(func, filter); } diff --git a/yql/essentials/public/udf/udf_log.h b/yql/essentials/public/udf/udf_log.h index 3cc09875571..2e39ad1e040 100644 --- a/yql/essentials/public/udf/udf_log.h +++ b/yql/essentials/public/udf/udf_log.h @@ -28,6 +28,7 @@ inline bool IsLogLevelAllowed(ELogLevel message, ELogLevel threshold) { return static_cast<ui32>(message) <= static_cast<ui32>(threshold); } +TString LogLevelAvailables(); TStringBuf LevelToString(ELogLevel level); TMaybe<ELogLevel> TryLevelFromString(TStringBuf str); diff --git a/yql/essentials/tests/sql/minirun/part8/canondata/result.json b/yql/essentials/tests/sql/minirun/part8/canondata/result.json index 94d8c6547e4..43ee13546b2 100644 --- a/yql/essentials/tests/sql/minirun/part8/canondata/result.json +++ b/yql/essentials/tests/sql/minirun/part8/canondata/result.json @@ -1405,6 +1405,23 @@ "uri": "https://{canondata_backend}/1937429/f07d607c2797952b0e405c5e49adc94025f9df81/resource.tar.gz#test.test_seq_mode-shared_subquery_expr-default.txt-Results_/results.txt" } ], + "test.test[udf-logger_resolve--Debug]": [ + { + "checksum": "df551ab2d87bb2dec98cc1e869a6b915", + "size": 503, + "uri": "https://{canondata_backend}/1936273/e131662f629dddf3480e2361346c89c0c6c938f2/resource.tar.gz#test.test_udf-logger_resolve--Debug_/opt.yql" + } + ], + "test.test[udf-logger_resolve--Results]": [ + { + "checksum": "6bf5504398cb6997843ff2b80cb76c01", + "size": 653, + "uri": "https://{canondata_backend}/1936273/e131662f629dddf3480e2361346c89c0c6c938f2/resource.tar.gz#test.test_udf-logger_resolve--Results_/results.txt" + }, + { + "uri": "file://test.test_udf-logger_resolve--Results_/extracted" + } + ], "test.test[udf-sqlproject_grounds-default.txt-Debug]": [ { "checksum": "e3bc4f97fbe2d5b316824ae1df155a07", diff --git a/yql/essentials/tests/sql/minirun/part8/canondata/test.test_udf-logger_resolve--Results_/extracted b/yql/essentials/tests/sql/minirun/part8/canondata/test.test_udf-logger_resolve--Results_/extracted new file mode 100644 index 00000000000..3e9789b39ba --- /dev/null +++ b/yql/essentials/tests/sql/minirun/part8/canondata/test.test_udf-logger_resolve--Results_/extracted @@ -0,0 +1,9 @@ +<tmp_path>/program.sql:<main>: Info: Type annotation + + <tmp_path>/program.sql:<main>:2:1: Info: At function: RemovePrefixMembers, At function: Unordered, At function: PersistableRepr, At function: OrderedSqlProject, At function: SqlProjectItem + select SimpleUdf::Logging(0,'foo'); + ^ + <tmp_path>/program.sql:<main>:2:19: Info: At function: Apply, At function: Udf, At SimpleUdf.Logging + select SimpleUdf::Logging(0,'foo'); + ^ + <tmp_path>/program.sql:<main>: Info: 1970-01-01T00:00:01.000000Z SimpleUdf.Logging [Debug] DeclareSignature
\ No newline at end of file diff --git a/yql/essentials/tests/sql/sql2yql/canondata/result.json b/yql/essentials/tests/sql/sql2yql/canondata/result.json index 95e786a1edc..635dbdb17fb 100644 --- a/yql/essentials/tests/sql/sql2yql/canondata/result.json +++ b/yql/essentials/tests/sql/sql2yql/canondata/result.json @@ -7083,6 +7083,13 @@ "uri": "https://{canondata_backend}/1942173/99e88108149e222741552e7e6cddef041d6a2846/resource.tar.gz#test_sql2yql.test_udf-generic_udf_/sql.yql" } ], + "test_sql2yql.test[udf-logger_resolve]": [ + { + "checksum": "30cab5ebc3fbccd46acd58ad689db4d1", + "size": 1145, + "uri": "https://{canondata_backend}/1942278/9db37083b795a3b23a916345e41eb37f06a87a0a/resource.tar.gz#test_sql2yql.test_udf-logger_resolve_/sql.yql" + } + ], "test_sql2yql.test[udf-named_args]": [ { "checksum": "86a596bf2cc0c1ee63950cb2862ca4f7", @@ -10961,6 +10968,11 @@ "uri": "file://test_sql_format.test_udf-generic_udf_/formatted.sql" } ], + "test_sql_format.test[udf-logger_resolve]": [ + { + "uri": "file://test_sql_format.test_udf-logger_resolve_/formatted.sql" + } + ], "test_sql_format.test[udf-named_args]": [ { "uri": "file://test_sql_format.test_udf-named_args_/formatted.sql" diff --git a/yql/essentials/tests/sql/sql2yql/canondata/test_sql_format.test_udf-logger_resolve_/formatted.sql b/yql/essentials/tests/sql/sql2yql/canondata/test_sql_format.test_udf-logger_resolve_/formatted.sql new file mode 100644 index 00000000000..b79d53faf1c --- /dev/null +++ b/yql/essentials/tests/sql/sql2yql/canondata/test_sql_format.test_udf-logger_resolve_/formatted.sql @@ -0,0 +1,5 @@ +PRAGMA RuntimeLogLevel = 'trace'; + +SELECT + SimpleUdf::Logging(0, 'foo') +; diff --git a/yql/essentials/tests/sql/suites/udf/logger_resolve.cfg b/yql/essentials/tests/sql/suites/udf/logger_resolve.cfg new file mode 100644 index 00000000000..7ff79f488bf --- /dev/null +++ b/yql/essentials/tests/sql/suites/udf/logger_resolve.cfg @@ -0,0 +1,2 @@ +udf simple_udf + diff --git a/yql/essentials/tests/sql/suites/udf/logger_resolve.sql b/yql/essentials/tests/sql/suites/udf/logger_resolve.sql new file mode 100644 index 00000000000..70ca8efcffe --- /dev/null +++ b/yql/essentials/tests/sql/suites/udf/logger_resolve.sql @@ -0,0 +1,2 @@ +pragma RuntimeLogLevel='trace'; +select SimpleUdf::Logging(0,'foo'); diff --git a/yql/essentials/tools/udf_resolver/discover.cpp b/yql/essentials/tools/udf_resolver/discover.cpp index 3b801ae705f..a290917a5a9 100644 --- a/yql/essentials/tools/udf_resolver/discover.cpp +++ b/yql/essentials/tools/udf_resolver/discover.cpp @@ -5,6 +5,7 @@ #include <yql/essentials/minikql/mkql_node.h> #include <yql/essentials/minikql/mkql_type_builder.h> #include <yql/essentials/minikql/mkql_utils.h> +#include <yql/essentials/utils/time_provider.h> #include <yql/essentials/providers/common/schema/mkql/yql_mkql_schema.h> #include <yql/essentials/providers/common/proto/udf_resolver.pb.h> @@ -47,18 +48,26 @@ NYql::TResolveResult DoDiscover(const NYql::TResolve& inMsg, IMutableFunctionReg } } + NYql::TFunctionResult* udfRes = nullptr; + + auto logProvider = NUdf::MakeLogProvider( + [&](const NUdf::TStringRef& component, NUdf::ELogLevel level, const NUdf::TStringRef& message) { + udfRes->AddMessages(TStringBuilder() << NYql::GetTimeProvider()->Now() << " " << component << " [" << level << "] " << message); + }, + static_cast<NUdf::ELogLevel>(inMsg.GetRuntimeLogLevel())); + for (const auto& module : functionRegistry.GetAllModuleNames()) { const auto& functions = functionRegistry.GetModuleFunctions(module); for (auto& f : functions) { const TString funcName = NKikimr::NMiniKQL::FullName(module, f.first); - auto udfRes = outMsg.AddUdfs(); + udfRes = outMsg.AddUdfs(); udfRes->SetName(funcName); udfRes->SetIsTypeAwareness(f.second.IsTypeAwareness); TFunctionTypeInfo funcInfo; if (!f.second.IsTypeAwareness) { auto status = functionRegistry.FindFunctionTypeInfo(env, typeInfoHelper, - nullptr, funcName, nullptr, nullptr, NUdf::IUdfModule::TFlags::TypesOnly, {}, nullptr, nullptr, &funcInfo); + nullptr, funcName, nullptr, nullptr, NUdf::IUdfModule::TFlags::TypesOnly, {}, nullptr, logProvider.Get(), &funcInfo); if (!status.IsOk()) { udfRes->SetError("Failed to resolve signature, error: " + status.GetError()); @@ -94,8 +103,9 @@ void Print(const NYql::TResolveResult& result, IOutputStream& out, bool printAsP out << "UDF count: " << result.UdfsSize() << Endl; } -void DiscoverInFiles(const TVector<TString>& udfPaths, IOutputStream& out, bool printAsProto) { +void DiscoverInFiles(const TVector<TString>& udfPaths, IOutputStream& out, bool printAsProto, NYql::NUdf::ELogLevel logLevel) { NYql::TResolve inMsg; + inMsg.SetRuntimeLogLevel(static_cast<ui32>(logLevel)); for (auto& path : udfPaths) { auto import = inMsg.AddImports(); import->SetPath(path); @@ -112,14 +122,14 @@ void DiscoverInFiles(const TVector<TString>& udfPaths, IOutputStream& out, bool } -void DiscoverInDir(const TString& dir, IOutputStream& out, bool printAsProto) { +void DiscoverInDir(const TString& dir, IOutputStream& out, bool printAsProto, NYql::NUdf::ELogLevel logLevel) { TVector<TString> udfPaths; NMiniKQL::FindUdfsInDir(dir, &udfPaths); - DiscoverInFiles(udfPaths, out, printAsProto); + DiscoverInFiles(udfPaths, out, printAsProto, logLevel); } -void DiscoverInFile(const TString& filePath, IOutputStream& out, bool printAsProto) { - DiscoverInFiles({ filePath }, out, printAsProto); +void DiscoverInFile(const TString& filePath, IOutputStream& out, bool printAsProto, NYql::NUdf::ELogLevel logLevel) { + DiscoverInFiles({ filePath }, out, printAsProto, logLevel); } void Discover(IInputStream& in, IOutputStream& out, bool printAsProto) { diff --git a/yql/essentials/tools/udf_resolver/discover.h b/yql/essentials/tools/udf_resolver/discover.h index 1a45c7a6440..7c995b7f656 100644 --- a/yql/essentials/tools/udf_resolver/discover.h +++ b/yql/essentials/tools/udf_resolver/discover.h @@ -2,14 +2,15 @@ #include <yql/essentials/providers/common/proto/udf_resolver.pb.h> #include <yql/essentials/minikql/mkql_function_registry.h> +#include <yql/essentials/public/udf/udf_log.h> #include <util/generic/hash.h> #include <util/stream/input.h> #include <util/stream/output.h> namespace NUdfResolver { -void DiscoverInDir(const TString& dir, IOutputStream& out, bool printAsProto); -void DiscoverInFile(const TString& filePath, IOutputStream& out, bool printAsProto); +void DiscoverInDir(const TString& dir, IOutputStream& out, bool printAsProto, NYql::NUdf::ELogLevel logLevel); +void DiscoverInFile(const TString& filePath, IOutputStream& out, bool printAsProto, NYql::NUdf::ELogLevel logLevel); void Discover(IInputStream& in, IOutputStream& out, bool printAsProto); void FillImportResultModules(const THashSet<TString>& modules, NYql::TImportResult& importRes); ; diff --git a/yql/essentials/tools/udf_resolver/udf_resolver.cpp b/yql/essentials/tools/udf_resolver/udf_resolver.cpp index ce5b648be2b..27ab6f87d48 100644 --- a/yql/essentials/tools/udf_resolver/udf_resolver.cpp +++ b/yql/essentials/tools/udf_resolver/udf_resolver.cpp @@ -12,6 +12,8 @@ #include <yql/essentials/minikql/mkql_type_builder.h> #include <yql/essentials/minikql/mkql_program_builder.h> #include <yql/essentials/minikql/mkql_utils.h> +#include <yql/essentials/public/udf/udf_log.h> +#include <yql/essentials/utils/time_provider.h> #include <library/cpp/getopt/last_getopt.h> @@ -147,9 +149,17 @@ void ResolveUDFs() { } } + NYql::TFunctionResult* udfRes = nullptr; + + auto logProvider = NUdf::MakeLogProvider( + [&](const NUdf::TStringRef& component, NUdf::ELogLevel level, const NUdf::TStringRef& message) { + udfRes->AddMessages(TStringBuilder() << NYql::GetTimeProvider()->Now() << " " << component << " [" << level << "] " << message); + }, + static_cast<NUdf::ELogLevel>(inMsg.GetRuntimeLogLevel())); + for (size_t i = 0; i < inMsg.UdfsSize(); ++i) { auto& udf = inMsg.GetUdfs(i); - auto udfRes = outMsg.AddUdfs(); + udfRes = outMsg.AddUdfs(); try { TProgramBuilder pgmBuilder(env, *newRegistry); TType* mkqlUserType = nullptr; @@ -165,7 +175,7 @@ void ResolveUDFs() { TFunctionTypeInfo funcInfo; auto status = newRegistry->FindFunctionTypeInfo(env, typeInfoHelper, nullptr, - udf.GetName(), mkqlUserType, udf.GetTypeConfig(), NUdf::IUdfModule::TFlags::TypesOnly, {}, nullptr, nullptr, &funcInfo); + udf.GetName(), mkqlUserType, udf.GetTypeConfig(), NUdf::IUdfModule::TFlags::TypesOnly, {}, nullptr, logProvider.Get(), &funcInfo); if (!status.IsOk()) { udfRes->SetError(TStringBuilder() << "Failed to find UDF function: " << udf.GetName() << ", reason: " << status.GetError()); @@ -265,6 +275,7 @@ int main(int argc, char **argv) { TString user; TString group; bool printAsProto = true; + NUdf::ELogLevel logLevel = NUdf::ELogLevel::Info; NLastGetopt::TOpts opts = NLastGetopt::TOpts::Default(); opts.AddLongOption('L', "list", "List UDF modules in specified directory") @@ -298,6 +309,16 @@ int main(int argc, char **argv) { .Optional() .NoArgument(); + opts.AddLongOption("log-level", "Runtime log level, available values: " + NUdf::LogLevelAvailables()) + .Handler1T<TString>([&](const TString& level) { + auto res = NUdf::TryLevelFromString(level); + if (!res) { + throw yexception() << "Invalid log level: " << level; + } + + logLevel = *res; + }); + opts.SetFreeArgsNum(0); NLastGetopt::TOptsParseResult res(&opts, argc, argv); @@ -492,9 +513,9 @@ int main(int argc, char **argv) { NFs::EnsureExists(path); TFileStat fstat(path); if (fstat.IsDir()) { - NUdfResolver::DiscoverInDir(path, Cout, printAsProto); + NUdfResolver::DiscoverInDir(path, Cout, printAsProto, logLevel); } else { - NUdfResolver::DiscoverInFile(path, Cout, printAsProto); + NUdfResolver::DiscoverInFile(path, Cout, printAsProto, logLevel); } return 0; } diff --git a/yql/essentials/udfs/test/simple/simple_udf.cpp b/yql/essentials/udfs/test/simple/simple_udf.cpp index ec35563323c..759f21380d7 100644 --- a/yql/essentials/udfs/test/simple/simple_udf.cpp +++ b/yql/essentials/udfs/test/simple/simple_udf.cpp @@ -241,9 +241,9 @@ private: class TLogging : public TBoxedValue { public: - TLogging(TLoggerPtr logger) + TLogging(TLoggerPtr logger, TLogComponentId component) : Logger(logger) - , Component(logger->RegisterComponent(Name())) + , Component(component) {} TUnboxedValue Run(const IValueBuilder* valueBuilder, const TUnboxedValuePod* args) const final { @@ -266,8 +266,11 @@ public: argBuilder->Add<char*>(); argBuilder->Done().Returns<TVoid>(); + auto logger = builder.MakeLogger(false); + auto component = logger->RegisterComponent(Name()); + logger->Log(component, ELogLevel::Debug, "DeclareSignature"); if (!typesOnly) { - builder.Implementation(new TLogging(builder.MakeLogger(false))); + builder.Implementation(new TLogging(logger, component)); } return true; } diff --git a/yql/essentials/utils/time_provider.cpp b/yql/essentials/utils/time_provider.cpp new file mode 100644 index 00000000000..d636f72ebc3 --- /dev/null +++ b/yql/essentials/utils/time_provider.cpp @@ -0,0 +1,11 @@ +#include "time_provider.h" +#include <util/system/env.h> + +namespace NYql { + +TIntrusivePtr<ITimeProvider> GetTimeProvider() { + static TIntrusivePtr<ITimeProvider> Provider = !!GetEnv("YQL_DETERMINISTIC_MODE") ? CreateDeterministicTimeProvider(1) : CreateDefaultTimeProvider(); + return Provider; +} + +} // namespace NYql diff --git a/yql/essentials/utils/time_provider.h b/yql/essentials/utils/time_provider.h new file mode 100644 index 00000000000..f7b30acab15 --- /dev/null +++ b/yql/essentials/utils/time_provider.h @@ -0,0 +1,8 @@ +#pragma once +#include <library/cpp/time_provider/time_provider.h> + +namespace NYql { + +TIntrusivePtr<ITimeProvider> GetTimeProvider(); + +} // namespace NYql diff --git a/yql/essentials/utils/ya.make b/yql/essentials/utils/ya.make index 562da8d0343..8d4d279b956 100644 --- a/yql/essentials/utils/ya.make +++ b/yql/essentials/utils/ya.make @@ -36,6 +36,8 @@ SRCS( sort.h swap_bytes.cpp swap_bytes.h + time_provider.h + time_provider.cpp tty.cpp tty.h url_builder.cpp @@ -47,6 +49,7 @@ SRCS( ) PEERDIR( + library/cpp/time_provider library/cpp/digest/md5 library/cpp/string_utils/quote library/cpp/threading/future |