github.com/ydb-platform/ydb-go-sdk/v3@v3.89.2/log/query.go (about) 1 package log 2 3 import ( 4 "time" 5 6 "github.com/ydb-platform/ydb-go-sdk/v3/internal/kv" 7 "github.com/ydb-platform/ydb-go-sdk/v3/internal/xerrors" 8 "github.com/ydb-platform/ydb-go-sdk/v3/trace" 9 ) 10 11 // Query makes trace.Query with logging events from details 12 func Query(l Logger, d trace.Detailer, opts ...Option) (t trace.Query) { 13 return internalQuery(wrapLogger(l, opts...), d) 14 } 15 16 //nolint:gocyclo,funlen 17 func internalQuery( 18 l *wrapper, //nolint:interfacer 19 d trace.Detailer, 20 ) trace.Query { 21 return trace.Query{ 22 OnNew: func(info trace.QueryNewStartInfo) func(info trace.QueryNewDoneInfo) { 23 if d.Details()&trace.QueryEvents == 0 { 24 return nil 25 } 26 ctx := with(*info.Context, TRACE, "ydb", "query", "new") 27 l.Log(ctx, "start") 28 start := time.Now() 29 30 return func(info trace.QueryNewDoneInfo) { 31 l.Log(WithLevel(ctx, INFO), "done", 32 kv.Latency(start), 33 ) 34 } 35 }, 36 OnClose: func(info trace.QueryCloseStartInfo) func(info trace.QueryCloseDoneInfo) { 37 if d.Details()&trace.QueryEvents == 0 { 38 return nil 39 } 40 ctx := with(*info.Context, TRACE, "ydb", "query", "close") 41 l.Log(ctx, "start") 42 start := time.Now() 43 44 return func(info trace.QueryCloseDoneInfo) { 45 if info.Error == nil { 46 l.Log(ctx, "done", 47 kv.Latency(start), 48 ) 49 } else { 50 lvl := WARN 51 if !xerrors.IsYdb(info.Error) { 52 lvl = DEBUG 53 } 54 l.Log(WithLevel(ctx, lvl), "failed", 55 kv.Latency(start), 56 kv.Error(info.Error), 57 kv.Version(), 58 ) 59 } 60 } 61 }, 62 OnPoolNew: func(info trace.QueryPoolNewStartInfo) func(trace.QueryPoolNewDoneInfo) { 63 if d.Details()&trace.QueryPoolEvents == 0 { 64 return nil 65 } 66 ctx := with(*info.Context, TRACE, "ydb", "query", "pool", "new") 67 l.Log(ctx, "start") 68 start := time.Now() 69 70 return func(info trace.QueryPoolNewDoneInfo) { 71 l.Log(WithLevel(ctx, INFO), "done", 72 kv.Latency(start), 73 kv.Int("Limit", info.Limit), 74 ) 75 } 76 }, 77 OnPoolClose: func(info trace.QueryPoolCloseStartInfo) func(trace.QueryPoolCloseDoneInfo) { 78 if d.Details()&trace.QueryPoolEvents == 0 { 79 return nil 80 } 81 ctx := with(*info.Context, TRACE, "ydb", "query", "pool", "close") 82 l.Log(ctx, "start") 83 start := time.Now() 84 85 return func(info trace.QueryPoolCloseDoneInfo) { 86 if info.Error == nil { 87 l.Log(ctx, "done", 88 kv.Latency(start), 89 ) 90 } else { 91 lvl := WARN 92 if !xerrors.IsYdb(info.Error) { 93 lvl = DEBUG 94 } 95 l.Log(WithLevel(ctx, lvl), "failed", 96 kv.Latency(start), 97 kv.Error(info.Error), 98 kv.Version(), 99 ) 100 } 101 } 102 }, 103 OnPoolTry: func(info trace.QueryPoolTryStartInfo) func(trace.QueryPoolTryDoneInfo) { 104 if d.Details()&trace.QueryPoolEvents == 0 { 105 return nil 106 } 107 ctx := with(*info.Context, TRACE, "ydb", "query", "pool", "try") 108 l.Log(ctx, "start") 109 start := time.Now() 110 111 return func(info trace.QueryPoolTryDoneInfo) { 112 if info.Error == nil { 113 l.Log(ctx, "done", 114 kv.Latency(start), 115 ) 116 } else { 117 lvl := WARN 118 if !xerrors.IsYdb(info.Error) { 119 lvl = DEBUG 120 } 121 l.Log(WithLevel(ctx, lvl), "failed", 122 kv.Latency(start), 123 kv.Error(info.Error), 124 kv.Version(), 125 ) 126 } 127 } 128 }, 129 OnPoolWith: func(info trace.QueryPoolWithStartInfo) func(trace.QueryPoolWithDoneInfo) { 130 if d.Details()&trace.QueryPoolEvents == 0 { 131 return nil 132 } 133 ctx := with(*info.Context, DEBUG, "ydb", "query", "pool", "with") 134 l.Log(ctx, "start") 135 start := time.Now() 136 137 return func(info trace.QueryPoolWithDoneInfo) { 138 if info.Error == nil { 139 l.Log(ctx, "done", 140 kv.Latency(start), 141 kv.Int("Attempts", info.Attempts), 142 ) 143 } else { 144 lvl := ERROR 145 if !xerrors.IsYdb(info.Error) { 146 lvl = DEBUG 147 } 148 l.Log(WithLevel(ctx, lvl), "failed", 149 kv.Latency(start), 150 kv.Error(info.Error), 151 kv.Int("Attempts", info.Attempts), 152 kv.Version(), 153 ) 154 } 155 } 156 }, 157 OnPoolPut: func(info trace.QueryPoolPutStartInfo) func(trace.QueryPoolPutDoneInfo) { 158 if d.Details()&trace.QueryPoolEvents == 0 { 159 return nil 160 } 161 ctx := with(*info.Context, TRACE, "ydb", "query", "pool", "put") 162 l.Log(ctx, "start") 163 start := time.Now() 164 165 return func(info trace.QueryPoolPutDoneInfo) { 166 if info.Error == nil { 167 l.Log(ctx, "done", 168 kv.Latency(start), 169 ) 170 } else { 171 lvl := WARN 172 if !xerrors.IsYdb(info.Error) { 173 lvl = DEBUG 174 } 175 l.Log(WithLevel(ctx, lvl), "failed", 176 kv.Latency(start), 177 kv.Error(info.Error), 178 kv.Version(), 179 ) 180 } 181 } 182 }, 183 OnPoolGet: func(info trace.QueryPoolGetStartInfo) func(trace.QueryPoolGetDoneInfo) { 184 if d.Details()&trace.QueryPoolEvents == 0 { 185 return nil 186 } 187 ctx := with(*info.Context, TRACE, "ydb", "query", "pool", "get") 188 l.Log(ctx, "start") 189 start := time.Now() 190 191 return func(info trace.QueryPoolGetDoneInfo) { 192 if info.Error == nil { 193 l.Log(ctx, "done", 194 kv.Latency(start), 195 ) 196 } else { 197 lvl := WARN 198 if !xerrors.IsYdb(info.Error) { 199 lvl = DEBUG 200 } 201 l.Log(WithLevel(ctx, lvl), "failed", 202 kv.Latency(start), 203 kv.Error(info.Error), 204 kv.Version(), 205 ) 206 } 207 } 208 }, 209 OnDo: func(info trace.QueryDoStartInfo) func(trace.QueryDoDoneInfo) { 210 if d.Details()&trace.QueryEvents == 0 { 211 return nil 212 } 213 ctx := with(*info.Context, TRACE, "ydb", "query", "do") 214 l.Log(ctx, "start") 215 start := time.Now() 216 217 return func(info trace.QueryDoDoneInfo) { 218 if info.Error == nil { 219 l.Log(ctx, "done", 220 kv.Latency(start), 221 kv.Int("attempts", info.Attempts), 222 ) 223 } else { 224 lvl := ERROR 225 if !xerrors.IsYdb(info.Error) { 226 lvl = DEBUG 227 } 228 l.Log(WithLevel(ctx, lvl), "failed", 229 kv.Latency(start), 230 kv.Error(info.Error), 231 kv.Int("attempts", info.Attempts), 232 kv.Version(), 233 ) 234 } 235 } 236 }, 237 OnDoTx: func(info trace.QueryDoTxStartInfo) func(trace.QueryDoTxDoneInfo) { 238 if d.Details()&trace.QueryEvents == 0 { 239 return nil 240 } 241 ctx := with(*info.Context, TRACE, "ydb", "query", "do", "tx") 242 l.Log(ctx, "start") 243 start := time.Now() 244 245 return func(info trace.QueryDoTxDoneInfo) { 246 if info.Error == nil { 247 l.Log(ctx, "done", 248 kv.Latency(start), 249 kv.Int("attempts", info.Attempts), 250 ) 251 } else { 252 lvl := ERROR 253 if !xerrors.IsYdb(info.Error) { 254 lvl = DEBUG 255 } 256 l.Log(WithLevel(ctx, lvl), "failed", 257 kv.Latency(start), 258 kv.Error(info.Error), 259 kv.Int("attempts", info.Attempts), 260 kv.Version(), 261 ) 262 } 263 } 264 }, 265 OnExec: func(info trace.QueryExecStartInfo) func(trace.QueryExecDoneInfo) { 266 if d.Details()&trace.QueryEvents == 0 { 267 return nil 268 } 269 ctx := with(*info.Context, TRACE, "ydb", "query", "exec") 270 l.Log(ctx, "start") 271 start := time.Now() 272 273 return func(info trace.QueryExecDoneInfo) { 274 if info.Error == nil { 275 l.Log(ctx, "done", 276 kv.Latency(start), 277 ) 278 } else { 279 lvl := ERROR 280 if !xerrors.IsYdb(info.Error) { 281 lvl = DEBUG 282 } 283 l.Log(WithLevel(ctx, lvl), "failed", 284 kv.Latency(start), 285 kv.Error(info.Error), 286 kv.Version(), 287 ) 288 } 289 } 290 }, 291 OnQuery: func(info trace.QueryQueryStartInfo) func(trace.QueryQueryDoneInfo) { 292 if d.Details()&trace.QueryEvents == 0 { 293 return nil 294 } 295 ctx := with(*info.Context, TRACE, "ydb", "query", "query") 296 l.Log(ctx, "start") 297 start := time.Now() 298 299 return func(info trace.QueryQueryDoneInfo) { 300 if info.Error == nil { 301 l.Log(ctx, "done", 302 kv.Latency(start), 303 ) 304 } else { 305 lvl := ERROR 306 if !xerrors.IsYdb(info.Error) { 307 lvl = DEBUG 308 } 309 l.Log(WithLevel(ctx, lvl), "failed", 310 kv.Latency(start), 311 kv.Error(info.Error), 312 kv.Version(), 313 ) 314 } 315 } 316 }, 317 OnQueryRow: func(info trace.QueryQueryRowStartInfo) func(trace.QueryQueryRowDoneInfo) { 318 if d.Details()&trace.QueryEvents == 0 { 319 return nil 320 } 321 ctx := with(*info.Context, TRACE, "ydb", "query", "query", "row") 322 l.Log(ctx, "start") 323 start := time.Now() 324 325 return func(info trace.QueryQueryRowDoneInfo) { 326 if info.Error == nil { 327 l.Log(ctx, "done", 328 kv.Latency(start), 329 ) 330 } else { 331 lvl := ERROR 332 if !xerrors.IsYdb(info.Error) { 333 lvl = DEBUG 334 } 335 l.Log(WithLevel(ctx, lvl), "failed", 336 kv.Latency(start), 337 kv.Error(info.Error), 338 kv.Version(), 339 ) 340 } 341 } 342 }, 343 OnQueryResultSet: func(info trace.QueryQueryResultSetStartInfo) func(trace.QueryQueryResultSetDoneInfo) { 344 if d.Details()&trace.QueryEvents == 0 { 345 return nil 346 } 347 ctx := with(*info.Context, TRACE, "ydb", "query", "query", "result", "set") 348 l.Log(ctx, "start") 349 start := time.Now() 350 351 return func(info trace.QueryQueryResultSetDoneInfo) { 352 if info.Error == nil { 353 l.Log(ctx, "done", 354 kv.Latency(start), 355 ) 356 } else { 357 lvl := ERROR 358 if !xerrors.IsYdb(info.Error) { 359 lvl = DEBUG 360 } 361 l.Log(WithLevel(ctx, lvl), "failed", 362 kv.Latency(start), 363 kv.Error(info.Error), 364 kv.Version(), 365 ) 366 } 367 } 368 }, 369 OnSessionCreate: func(info trace.QuerySessionCreateStartInfo) func(info trace.QuerySessionCreateDoneInfo) { 370 if d.Details()&trace.QuerySessionEvents == 0 { 371 return nil 372 } 373 ctx := with(*info.Context, TRACE, "ydb", "query", "session", "create") 374 l.Log(ctx, "start") 375 start := time.Now() 376 377 return func(info trace.QuerySessionCreateDoneInfo) { 378 if info.Error == nil { 379 l.Log(ctx, "done", 380 kv.Latency(start), 381 kv.String("session_id", info.Session.ID()), 382 kv.String("session_status", info.Session.Status()), 383 ) 384 } else { 385 lvl := WARN 386 if !xerrors.IsYdb(info.Error) { 387 lvl = DEBUG 388 } 389 l.Log(WithLevel(ctx, lvl), "done", 390 kv.Latency(start), 391 kv.Error(info.Error), 392 kv.Version(), 393 ) 394 } 395 } 396 }, 397 OnSessionAttach: func(info trace.QuerySessionAttachStartInfo) func(info trace.QuerySessionAttachDoneInfo) { 398 if d.Details()&trace.QuerySessionEvents == 0 { 399 return nil 400 } 401 ctx := with(*info.Context, TRACE, "ydb", "query", "session", "attach") 402 l.Log(ctx, "start", 403 kv.String("session_id", info.Session.ID()), 404 kv.String("session_status", info.Session.Status()), 405 ) 406 start := time.Now() 407 408 return func(info trace.QuerySessionAttachDoneInfo) { 409 if info.Error == nil { 410 l.Log(ctx, "done", 411 kv.Latency(start), 412 ) 413 } else { 414 lvl := WARN 415 if !xerrors.IsYdb(info.Error) { 416 lvl = DEBUG 417 } 418 l.Log(WithLevel(ctx, lvl), "failed", 419 kv.Latency(start), 420 kv.Error(info.Error), 421 kv.Version(), 422 ) 423 } 424 } 425 }, 426 OnSessionDelete: func(info trace.QuerySessionDeleteStartInfo) func(info trace.QuerySessionDeleteDoneInfo) { 427 if d.Details()&trace.QuerySessionEvents == 0 { 428 return nil 429 } 430 ctx := with(*info.Context, TRACE, "ydb", "query", "session", "delete") 431 l.Log(ctx, "start", 432 kv.String("session_id", info.Session.ID()), 433 kv.String("session_status", info.Session.Status()), 434 ) 435 start := time.Now() 436 437 return func(info trace.QuerySessionDeleteDoneInfo) { 438 if info.Error == nil { 439 l.Log(ctx, "done", 440 kv.Latency(start), 441 ) 442 } else { 443 lvl := WARN 444 if !xerrors.IsYdb(info.Error) { 445 lvl = DEBUG 446 } 447 l.Log(WithLevel(ctx, lvl), "failed", 448 kv.Latency(start), 449 kv.Error(info.Error), 450 kv.Version(), 451 ) 452 } 453 } 454 }, 455 OnSessionExec: func(info trace.QuerySessionExecStartInfo) func(info trace.QuerySessionExecDoneInfo) { 456 if d.Details()&trace.QuerySessionEvents == 0 { 457 return nil 458 } 459 ctx := with(*info.Context, TRACE, "ydb", "query", "session", "exec") 460 l.Log(ctx, "start", 461 kv.String("SessionID", info.Session.ID()), 462 kv.String("SessionStatus", info.Session.Status()), 463 kv.String("Query", info.Query), 464 ) 465 start := time.Now() 466 467 return func(info trace.QuerySessionExecDoneInfo) { 468 if info.Error == nil { 469 l.Log(ctx, "done", 470 kv.Latency(start), 471 ) 472 } else { 473 lvl := WARN 474 if !xerrors.IsYdb(info.Error) { 475 lvl = DEBUG 476 } 477 l.Log(WithLevel(ctx, lvl), "failed", 478 kv.Latency(start), 479 kv.Error(info.Error), 480 kv.Version(), 481 ) 482 } 483 } 484 }, 485 OnSessionQuery: func(info trace.QuerySessionQueryStartInfo) func(info trace.QuerySessionQueryDoneInfo) { 486 if d.Details()&trace.QuerySessionEvents == 0 { 487 return nil 488 } 489 ctx := with(*info.Context, TRACE, "ydb", "query", "session", "query") 490 l.Log(ctx, "start", 491 kv.String("SessionID", info.Session.ID()), 492 kv.String("SessionStatus", info.Session.Status()), 493 kv.String("Query", info.Query), 494 ) 495 start := time.Now() 496 497 return func(info trace.QuerySessionQueryDoneInfo) { 498 if info.Error == nil { 499 l.Log(ctx, "done", 500 kv.Latency(start), 501 ) 502 } else { 503 lvl := WARN 504 if !xerrors.IsYdb(info.Error) { 505 lvl = DEBUG 506 } 507 l.Log(WithLevel(ctx, lvl), "failed", 508 kv.Latency(start), 509 kv.Error(info.Error), 510 kv.Version(), 511 ) 512 } 513 } 514 }, 515 OnSessionBegin: func(info trace.QuerySessionBeginStartInfo) func(info trace.QuerySessionBeginDoneInfo) { 516 if d.Details()&trace.QuerySessionEvents == 0 { 517 return nil 518 } 519 ctx := with(*info.Context, TRACE, "ydb", "query", "session", "begin") 520 l.Log(ctx, "start", 521 kv.String("SessionID", info.Session.ID()), 522 kv.String("SessionStatus", info.Session.Status()), 523 ) 524 start := time.Now() 525 526 return func(info trace.QuerySessionBeginDoneInfo) { 527 if info.Error == nil { 528 l.Log(WithLevel(ctx, DEBUG), "done", 529 kv.Latency(start), 530 kv.String("TransactionID", info.Tx.ID()), 531 ) 532 } else { 533 lvl := WARN 534 if !xerrors.IsYdb(info.Error) { 535 lvl = DEBUG 536 } 537 l.Log(WithLevel(ctx, lvl), "failed", 538 kv.Latency(start), 539 kv.Error(info.Error), 540 kv.Version(), 541 ) 542 } 543 } 544 }, 545 OnTxExec: func(info trace.QueryTxExecStartInfo) func(info trace.QueryTxExecDoneInfo) { 546 if d.Details()&trace.QueryTransactionEvents == 0 { 547 return nil 548 } 549 ctx := with(*info.Context, TRACE, "ydb", "query", "transaction", "exec") 550 l.Log(ctx, "start", 551 kv.String("SessionID", info.Session.ID()), 552 kv.String("TransactionID", info.Tx.ID()), 553 kv.String("SessionStatus", info.Session.Status()), 554 ) 555 start := time.Now() 556 557 return func(info trace.QueryTxExecDoneInfo) { 558 if info.Error == nil { 559 l.Log(WithLevel(ctx, DEBUG), "done", 560 kv.Latency(start), 561 ) 562 } else { 563 lvl := WARN 564 if !xerrors.IsYdb(info.Error) { 565 lvl = DEBUG 566 } 567 l.Log(WithLevel(ctx, lvl), "failed", 568 kv.Latency(start), 569 kv.Error(info.Error), 570 kv.Version(), 571 ) 572 } 573 } 574 }, 575 OnTxQuery: func(info trace.QueryTxQueryStartInfo) func(info trace.QueryTxQueryDoneInfo) { 576 if d.Details()&trace.QueryTransactionEvents == 0 { 577 return nil 578 } 579 ctx := with(*info.Context, TRACE, "ydb", "query", "transaction", "query") 580 l.Log(ctx, "start", 581 kv.String("SessionID", info.Session.ID()), 582 kv.String("TransactionID", info.Tx.ID()), 583 kv.String("SessionStatus", info.Session.Status()), 584 ) 585 start := time.Now() 586 587 return func(info trace.QueryTxQueryDoneInfo) { 588 if info.Error == nil { 589 l.Log(WithLevel(ctx, DEBUG), "done", 590 kv.Latency(start), 591 ) 592 } else { 593 lvl := WARN 594 if !xerrors.IsYdb(info.Error) { 595 lvl = DEBUG 596 } 597 l.Log(WithLevel(ctx, lvl), "failed", 598 kv.Latency(start), 599 kv.Error(info.Error), 600 kv.Version(), 601 ) 602 } 603 } 604 }, 605 OnResultNew: func(info trace.QueryResultNewStartInfo) func(info trace.QueryResultNewDoneInfo) { 606 if d.Details()&trace.QueryResultEvents == 0 { 607 return nil 608 } 609 ctx := with(*info.Context, TRACE, "ydb", "query", "result", "new") 610 l.Log(ctx, "start") 611 start := time.Now() 612 613 return func(info trace.QueryResultNewDoneInfo) { 614 if info.Error == nil { 615 l.Log(ctx, "done", 616 kv.Latency(start), 617 ) 618 } else { 619 lvl := WARN 620 if !xerrors.IsYdb(info.Error) { 621 lvl = DEBUG 622 } 623 l.Log(WithLevel(ctx, lvl), "failed", 624 kv.Latency(start), 625 kv.Error(info.Error), 626 kv.Version(), 627 ) 628 } 629 } 630 }, 631 OnResultNextPart: func(info trace.QueryResultNextPartStartInfo) func(info trace.QueryResultNextPartDoneInfo) { 632 if d.Details()&trace.QueryResultEvents == 0 { 633 return nil 634 } 635 ctx := with(*info.Context, TRACE, "ydb", "query", "result", "next", "part") 636 l.Log(ctx, "start") 637 start := time.Now() 638 639 return func(info trace.QueryResultNextPartDoneInfo) { 640 if info.Error == nil { 641 l.Log(ctx, "done", 642 kv.Stringer("stats", info.Stats), 643 kv.Latency(start), 644 ) 645 } else { 646 lvl := WARN 647 if !xerrors.IsYdb(info.Error) { 648 lvl = DEBUG 649 } 650 l.Log(WithLevel(ctx, lvl), "failed", 651 kv.Latency(start), 652 kv.Error(info.Error), 653 kv.Version(), 654 ) 655 } 656 } 657 }, 658 OnResultNextResultSet: func( 659 info trace.QueryResultNextResultSetStartInfo, 660 ) func( 661 info trace.QueryResultNextResultSetDoneInfo, 662 ) { 663 if d.Details()&trace.QueryResultEvents == 0 { 664 return nil 665 } 666 ctx := with(*info.Context, TRACE, "ydb", "query", "result", "next", "result", "set") 667 l.Log(ctx, "start") 668 start := time.Now() 669 670 return func(info trace.QueryResultNextResultSetDoneInfo) { 671 if info.Error == nil { 672 l.Log(ctx, "done", 673 kv.Latency(start), 674 ) 675 } else { 676 lvl := WARN 677 if !xerrors.IsYdb(info.Error) { 678 lvl = DEBUG 679 } 680 l.Log(WithLevel(ctx, lvl), "failed", 681 kv.Latency(start), 682 kv.Error(info.Error), 683 kv.Version(), 684 ) 685 } 686 } 687 }, 688 OnResultClose: func(info trace.QueryResultCloseStartInfo) func(info trace.QueryResultCloseDoneInfo) { 689 if d.Details()&trace.QueryResultEvents == 0 { 690 return nil 691 } 692 ctx := with(*info.Context, TRACE, "ydb", "query", "result", "close") 693 l.Log(ctx, "start") 694 start := time.Now() 695 696 return func(info trace.QueryResultCloseDoneInfo) { 697 if info.Error == nil { 698 l.Log(ctx, "done", 699 kv.Latency(start), 700 ) 701 } else { 702 lvl := WARN 703 if !xerrors.IsYdb(info.Error) { 704 lvl = DEBUG 705 } 706 l.Log(WithLevel(ctx, lvl), "failed", 707 kv.Latency(start), 708 kv.Error(info.Error), 709 kv.Version(), 710 ) 711 } 712 } 713 }, 714 } 715 }