Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat: add more detail log in chat api #453

Merged
merged 1 commit into from
Dec 27, 2023
Merged

Conversation

Abirdcfly
Copy link
Collaborator

@Abirdcfly Abirdcfly commented Dec 26, 2023

What type of PR is this?

/kind cleanup

What this PR does / why we need it

  1. Add more logging details
  2. Assign a random request ID to each request (or read the value of the standard request header: X-Request-ID from the request) to make it easier to filter the logs of individual requests.
  3. For each error in chat API, describe the error in detail (by fmt.Errorf("xxx:%w", err)), easy to locate the problem.
  4. Fix possible timeout when using zhipuai in streaming mode.
  5. Add event type error for chat streaming mode errors.

Which issue(s) this PR fixes

For #413

Special notes for your reviewer

-v=5 stream common request:

Details
I1226 16:40:55.277004   84204 requestid.go:17] "new request" requestID="80d4d046-2103-49ad-8218-9ab054403146"
I1226 16:40:55.277359   84204 chat.go:121] "start to receive messages..." requestID="80d4d046-2103-49ad-8218-9ab054403146"
I1226 16:40:55.286582   84204 app_run.go:236] "initnode prompt" requestID="80d4d046-2103-49ad-8218-9ab054403146"
I1226 16:40:55.286633   84204 app_run.go:224] "initnode llm" requestID="80d4d046-2103-49ad-8218-9ab054403146"
I1226 16:40:55.290618   84204 app_run.go:205] "initnode llmchain" requestID="80d4d046-2103-49ad-8218-9ab054403146"
I1226 16:40:55.290663   84204 app_run.go:145] "init application success starting nodes: []base.Node{(*base.Input)(0xc000340ee0), (*llm.LLM)(0xc0003db080)}\n" requestID="80d4d046-2103-49ad-8218-9ab054403146"
I1226 16:40:55.290685   84204 chat.go:106] "begin to run application" requestID="80d4d046-2103-49ad-8218-9ab054403146" appName="base-chat-with-bot" appNamespace="arcadia"
I1226 16:40:55.295672   84204 langchainllm.go:100] zhipuai: message type system not supported, just skip
I1226 16:40:55.295811   84204 langchainllm.go:103] all history prompts: []zhipuai.Prompt{zhipuai.Prompt{Role:"user", Content:"The following is a friendly conversation between a human and an AI. The AI is talkative and provides lots of specific details from its context. If the AI does not know the answer to a question, it truthfully says it does not know.\n\nCurrent conversation:\n\nHuman: 1+1=?\nAI:\n"}}
I1226 16:40:56.012701   84204 common.go:45] "stream out: " requestID="80d4d046-2103-49ad-8218-9ab054403146"
I1226 16:40:56.061931   84204 common.go:45] "stream out:1" requestID="80d4d046-2103-49ad-8218-9ab054403146"
I1226 16:40:56.118910   84204 common.go:45] "stream out:+" requestID="80d4d046-2103-49ad-8218-9ab054403146"
I1226 16:40:56.163663   84204 common.go:45] "stream out:1" requestID="80d4d046-2103-49ad-8218-9ab054403146"
I1226 16:40:56.267082   84204 common.go:45] "stream out:=" requestID="80d4d046-2103-49ad-8218-9ab054403146"
I1226 16:40:56.318437   84204 common.go:45] "stream out:2" requestID="80d4d046-2103-49ad-8218-9ab054403146"
I1226 16:40:56.368205   84204 common.go:45] "stream out:。" requestID="80d4d046-2103-49ad-8218-9ab054403146"
I1226 16:40:56.414135   84204 common.go:45] "stream out:这是一个" requestID="80d4d046-2103-49ad-8218-9ab054403146"
I1226 16:40:56.469689   84204 common.go:45] "stream out:基本的" requestID="80d4d046-2103-49ad-8218-9ab054403146"
I1226 16:40:56.526120   84204 common.go:45] "stream out:数学" requestID="80d4d046-2103-49ad-8218-9ab054403146"
I1226 16:40:56.566729   84204 common.go:45] "stream out:运算" requestID="80d4d046-2103-49ad-8218-9ab054403146"
I1226 16:40:56.616696   84204 common.go:45] "stream out:," requestID="80d4d046-2103-49ad-8218-9ab054403146"
I1226 16:40:56.665857   84204 common.go:45] "stream out:当" requestID="80d4d046-2103-49ad-8218-9ab054403146"
I1226 16:40:56.716682   84204 common.go:45] "stream out:我们将" requestID="80d4d046-2103-49ad-8218-9ab054403146"
I1226 16:40:56.765917   84204 common.go:45] "stream out:一个" requestID="80d4d046-2103-49ad-8218-9ab054403146"
I1226 16:40:56.815339   84204 common.go:45] "stream out:数字" requestID="80d4d046-2103-49ad-8218-9ab054403146"
I1226 16:40:56.867206   84204 common.go:45] "stream out:1" requestID="80d4d046-2103-49ad-8218-9ab054403146"
I1226 16:40:56.915047   84204 common.go:45] "stream out:与" requestID="80d4d046-2103-49ad-8218-9ab054403146"
I1226 16:40:56.964874   84204 common.go:45] "stream out:另一个" requestID="80d4d046-2103-49ad-8218-9ab054403146"
I1226 16:40:57.014557   84204 common.go:45] "stream out:数字" requestID="80d4d046-2103-49ad-8218-9ab054403146"
I1226 16:40:57.064027   84204 common.go:45] "stream out:1" requestID="80d4d046-2103-49ad-8218-9ab054403146"
I1226 16:40:57.115041   84204 common.go:45] "stream out:相" requestID="80d4d046-2103-49ad-8218-9ab054403146"
I1226 16:40:57.165943   84204 common.go:45] "stream out:加" requestID="80d4d046-2103-49ad-8218-9ab054403146"
I1226 16:40:57.217189   84204 common.go:45] "stream out:时" requestID="80d4d046-2103-49ad-8218-9ab054403146"
I1226 16:40:57.266356   84204 common.go:45] "stream out:," requestID="80d4d046-2103-49ad-8218-9ab054403146"
I1226 16:40:57.327440   84204 common.go:45] "stream out:结果" requestID="80d4d046-2103-49ad-8218-9ab054403146"
I1226 16:40:57.384062   84204 common.go:45] "stream out:是" requestID="80d4d046-2103-49ad-8218-9ab054403146"
I1226 16:40:57.432926   84204 common.go:45] "stream out:2" requestID="80d4d046-2103-49ad-8218-9ab054403146"
I1226 16:40:57.483672   84204 common.go:45] "stream out:。" requestID="80d4d046-2103-49ad-8218-9ab054403146"
I1226 16:40:57.544217   84204 llmchain.go:103] "use llmchain, blocking out:1+1=2。这是一个基本的数学运算,当我们将一个数字1与另一个数字1相加时,结果是2。" 9ab054403146"
I1226 16:40:57.544259   84204 chat.go:138] "end to receive messages" requestID="80d4d046-2103-49ad-8218-9ab054403146"
I1226 16:40:57.544294   84204 chat.go:149] "chat done" requestID="80d4d046-2103-49ad-8218-9ab054403146" req={Query:1+1=? ResponseMode:streaming ConversatinReqBody:{APPMetadata:{APPName:base-chat-with-bot AppNamespace:arcadia} ConversationID:} Debug:false}
[GIN] 2023/12/26 - 16:40:57 | 200 |  2.256294561s |       127.0.0.1 | POST     "/chat"

-v=5 blocking common request

Details
I1226 16:41:41.983277   84204 requestid.go:17] "new request" requestID="da265816-a204-4fd0-b25d-ff196de5ed4e"
I1226 16:41:41.987563   84204 app_run.go:236] "initnode prompt" requestID="da265816-a204-4fd0-b25d-ff196de5ed4e"
I1226 16:41:41.987588   84204 app_run.go:224] "initnode llm" requestID="da265816-a204-4fd0-b25d-ff196de5ed4e"
I1226 16:41:41.991422   84204 app_run.go:205] "initnode llmchain" requestID="da265816-a204-4fd0-b25d-ff196de5ed4e"
I1226 16:41:41.991458   84204 app_run.go:145] "init application success starting nodes: []base.Node{(*base.Input)(0xc0004620e0), (*llm.LLM)(0xc000368800)}\n" requestID="da265816-a204-4fd0-b25d-ff196de5ed4e"
I1226 16:41:41.991478   84204 chat.go:106] "begin to run application" requestID="da265816-a204-4fd0-b25d-ff196de5ed4e" appName="base-chat-with-bot" appNamespace="arcadia"
I1226 16:41:41.995179   84204 langchainllm.go:100] zhipuai: message type system not supported, just skip
I1226 16:41:41.995202   84204 langchainllm.go:103] all history prompts: []zhipuai.Prompt{zhipuai.Prompt{Role:"user", Content:"The following is a friendly conversation between a human and an AI. The AI is talkative and provides lots of specific details from its context. If the AI does not know the answer to a question, it truthfully says it does not know.\n\nCurrent conversation:\n\nHuman: 1+1=?\nAI:\n"}}
I1226 16:41:44.950649   84204 llmchain.go:103] "use llmchain, blocking out:1+1 equals 2. This is a basic arithmetic operation taught in schools. If you have any more questions or need assistance with something else, feel free to ask." requestID="da265816-a204-4fd0-b25d-ff196de5ed4e"
I1226 16:41:44.950843   84204 chat.go:149] "chat done" requestID="da265816-a204-4fd0-b25d-ff196de5ed4e" req={Query:1+1=? ResponseMode:streaming1 ConversatonReqBody:{APPMetadata:{APPName:base-chat-with-bot AppNamespace:arcadia} ConversationID:} Debug:false}
[GIN] 2023/12/26 - 16:41:44 | 200 |  2.967673532s |       127.0.0.1 | POST     "/chat"

stream common request:

Details
I1226 08:37:50.439728       1 requestid.go:17] "new request" requestID="a14db6ae-f9f5-4b3f-8287-8ee317e9f30f"
I1226 08:37:50.439811       1 chat.go:120] "start to receive messages..." requestID="a14db6ae-f9f5-4b3f-8287-8ee317e9f30f"
I1226 08:37:50.448921       1 chat.go:106] "begin to run application" requestID="a14db6ae-f9f5-4b3f-8287-8ee317e9f30f" appName="base-chat-with-bot" appNamespace="arcadia"
I1226 08:37:50.452382       1 langchainllm.go:100] zhipuai: message type system not supported, just skip
I1226 08:37:50.452402       1 langchainllm.go:103] all history prompts: []zhipuai.Prompt{zhipuai.Prompt{Role:"user", Content:"The following is a friendly conversation between a human and an AI. The AI is talkative and provides lots of specific details from its context. If the AI does not know the answer to a question, it truthfully says it does not know.\n\nCurrent conversation:\n\nHuman: 1+1=?\nAI:\n"}}
I1226 08:37:53.389725       1 chat.go:137] "end to receive messages" requestID="a14db6ae-f9f5-4b3f-8287-8ee317e9f30f"
[GIN] 2023/12/26 - 08:37:53 | 200 |  2.950079771s |       127.0.0.1 | POST     "/chat"

blocking common request:

Details
I1226 08:37:07.772825       1 requestid.go:17] "new request" requestID="bd1a3e2f-9fda-439f-b1f0-a78cb55c0623"
I1226 08:37:07.779274       1 chat.go:106] "begin to run application" requestID="bd1a3e2f-9fda-439f-b1f0-a78cb55c0623" appName="base-chat-with-bot" appNamespace="arcadia"
I1226 08:37:07.783413       1 langchainllm.go:100] zhipuai: message type system not supported, just skip
I1226 08:37:07.783440       1 langchainllm.go:103] all history prompts: []zhipuai.Prompt{zhipuai.Prompt{Role:"user", Content:"The following is a friendly conversation between a human and an AI. The AI is talkative and provides lots of specific details from its context. If the AI does not know the answer to a question, it truthfully says it does not know.\n\nCurrent conversation:\n\nHuman: 1+1=?\nAI:\n"}}
[GIN] 2023/12/26 - 08:37:09 | 200 |  2.055782199s |       127.0.0.1 | POST     "/chat"

@bjwswang
Copy link
Collaborator

For this conversation management https://github.com/kubeagi/arcadia/blob/main/apiserver/pkg/chat/chat.go#L42 , should we make this a conversation cache rather than only define two variables.

@Abirdcfly
Copy link
Collaborator Author

For this conversation management main/apiserver/pkg/chat/chat.go#L42 , should we make this a conversation cache rather than only define two variables.

yep, will cache it into postgress later, maybe in next version.

@@ -102,8 +103,8 @@ func AppRun(ctx context.Context, req ChatReqBody, respStream chan string) (*Chat
if err != nil {
return nil, err
}
klog.Infoln("begin to run application", obj.GetName())
out, err := appRun.Run(ctx, c, respStream, application.Input{Question: req.Query, NeedStream: req.ResponseMode == Streaming, History: conversation.History})
klog.FromContext(ctx).Info("begin to run application", "appName", req.APPName, "appNamespace", req.AppNamespace)
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

klog.V(5) ?

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Info or V(5).Info are both ok for me.
The update inherited from the original of @nkwangleiGIT .
IMO, this log conveniently allows us to calculate how much time was actually spent running the app, leaving aside the chat api initialization time.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That's good.

Seems to me

V(5)  ->  `DEBUG` 
V(3) ->  Info
V(1) ->  ERROR

Since we are going to release v0.1.0 , it's the time that we should make a agreement on logging levels.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

https://github.com/kubernetes/community/blob/master/contributors/devel/sig-instrumentation/logging.md#what-method-to-use

  • klog.InfoS - Structured logs to the INFO log. InfoS should be used for routine logging. It can also be used to log warnings for expected errors (errors that can happen during routine operations).
    Depending on log severity it's important to pick a proper verbosity level to ensure that consumer is neither under nor overwhelmed by log volume:
    • klog.V(0).InfoS = klog.InfoS - Generally useful for this to always be visible to a cluster operator
      • Programmer errors
      • Logging extra info about a panic
      • CLI argument handling
    • klog.V(1).InfoS - A reasonable default log level if you don't want verbosity.
      • Information about config (listening on X, watching Y)
      • Errors that repeat frequently that relate to conditions that can be corrected (pod detected as unhealthy)
    • klog.V(2).InfoS - Useful steady state information about the service and important log messages that may correlate to significant changes in the system. This is the recommended default log level for most systems.
      • Logging HTTP requests and their exit code
      • System state changing (killing pod)
      • Controller state change events (starting pods)
      • Scheduler log messages
    • klog.V(3).InfoS - Extended information about changes
      • More info about system state changes
    • klog.V(4).InfoS - Debug level verbosity
      • Logging in particularly thorny parts of code where you may want to come back later and check it
    • klog.V(5).InfoS - Trace level verbosity
      • Context to understand the steps leading up to errors and warnings
      • More information for troubleshooting reported issues

@bjwswang
Copy link
Collaborator

bjwswang commented Dec 27, 2023

For this conversation management main/apiserver/pkg/chat/chat.go#L42 , should we make this a conversation cache rather than only define two variables.

yep, will cache it into postgress later, maybe in next version.

Also we can use user/appid as the key to manage their own conversations which makes the mutext lock more fine-grained and effecient.

@Abirdcfly
Copy link
Collaborator Author

Also we can use user/appid as the key to manage their own conversations which makes the mutext lock more fine-grained and effecient.

hahaha, in next version, we will use pg, so mutex will be pg table lock or something.

@bjwswang
Copy link
Collaborator

Also we can use user/appid as the key to manage their own conversations which makes the mutext lock more fine-grained and effecient.

hahaha, in next version, we will use pg, so mutex will be pg table lock or something.

👀

@bjwswang
Copy link
Collaborator

Besides how about we use https://github.com/go-playground/validator for common struct validations?

Then we do not need to code too many if xx ==""

@bjwswang bjwswang merged commit c8a8a3a into kubeagi:main Dec 27, 2023
9 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants