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

Refactor HTTP client session handling; add curl debug logs #1870

Open
wants to merge 2 commits into
base: master
Choose a base branch
from

Conversation

chme
Copy link
Collaborator

@chme chme commented Feb 23, 2025

First commit contains a small refactoring to make reusing curl handles easier to use (with the struct http_client_session). Thread safety is now ensured by http_client_request(...) and the implementation details of struct http_client_session are now hidden, therefor the include of <curl.h> is now gone from http.h.

The second commit adds debug / spam logging for libcurl. Info messages, request/response headers are now logged with level DEBUG, request/response body and SSL data are logged with level SPAM.
Seeing the actual requests and responses made by libcurl can be very helpful when analyzing issues.

Example logs:

[2025-02-23 14:06:12] [DEBUG] [  library (1522)]     http: curl - using HTTP/2
[2025-02-23 14:06:12] [DEBUG] [  library (1522)]     http: curl - [HTTP/2] [1] OPENED stream for https://accounts.spotify.com/api/token
[2025-02-23 14:06:12] [DEBUG] [  library (1522)]     http: curl - [HTTP/2] [1] [:method: POST]
[2025-02-23 14:06:12] [DEBUG] [  library (1522)]     http: curl - [HTTP/2] [1] [:scheme: https]
[2025-02-23 14:06:12] [DEBUG] [  library (1522)]     http: curl - [HTTP/2] [1] [:authority: accounts.spotify.com]
[2025-02-23 14:06:12] [DEBUG] [  library (1522)]     http: curl - [HTTP/2] [1] [:path: /api/token]
[2025-02-23 14:06:12] [DEBUG] [  library (1522)]     http: curl - [HTTP/2] [1] [user-agent: owntone/28.12]
[2025-02-23 14:06:12] [DEBUG] [  library (1522)]     http: curl - [HTTP/2] [1] [accept: */*]
[2025-02-23 14:06:12] [DEBUG] [  library (1522)]     http: curl - [HTTP/2] [1] [content-length: 260]
[2025-02-23 14:06:12] [DEBUG] [  library (1522)]     http: curl - [HTTP/2] [1] [content-type: application/x-www-form-urlencoded]
[2025-02-23 14:06:12] [ SPAM] [  library (1522)]     http: curl > SSL Out
 0000  17 03 03 01 71                                   ....q
[2025-02-23 14:06:12] [ SPAM] [  library (1522)]     http: curl > SSL Out
 0000  17                                               .
[2025-02-23 14:06:12] [DEBUG] [  library (1522)]     http: curl > Request-Header - POST /api/token HTTP/2
Host: accounts.spotify.com
User-Agent: owntone/28.12
Accept: */*
Content-Length: 260
Content-Type: application/x-www-form-urlencoded

[2025-02-23 14:06:12] [ SPAM] [  library (1522)]     http: curl > Request-Body
 0000  67 72 61 6e 74 5f 74 79 70 65 3d 72 65 66 72 65  grant_type=refre
 0010  73 68 5f 74 6f 6b 65 6e 26 63 6c 69 65 6e 74 5f  sh_token&client_
 ...
[2025-02-23 14:06:12] [DEBUG] [  library (1522)]     http: curl < Response-Header - HTTP/2 200 
[2025-02-23 14:06:12] [DEBUG] [  library (1522)]     http: curl < Response-Header - date: Sun, 23 Feb 2025 13:06:12 GMT
[2025-02-23 14:06:12] [DEBUG] [  library (1522)]     http: curl < Response-Header - content-type: application/json
[2025-02-23 14:06:12] [DEBUG] [  library (1522)]     http: curl < Response-Header - content-length: 409
[2025-02-23 14:06:12] [DEBUG] [  library (1522)]     http: curl < Response-Header - vary: Accept-Encoding
[2025-02-23 14:06:12] [DEBUG] [  library (1522)]     http: curl < Response-Header - x-request-id: 5377fb9e-7ffb-4f00-b6bb-7c0d0112cf19
[2025-02-23 14:06:12] [DEBUG] [  library (1522)]     http: curl < Response-Header - set-cookie: __Host-device_id=AQDmtQhRtDWHhF...;Version=1;Path=/;Max-Age=2147483647;Secure;HttpOnly;SameSite=Lax
[2025-02-23 14:06:12] [DEBUG] [  library (1522)]     http: curl < Response-Header - set-cookie: sp_tr=false;Version=1;Domain=accounts.spotify.com;Path=/;Secure;SameSite=Lax
[2025-02-23 14:06:12] [DEBUG] [  library (1522)]     http: curl < Response-Header - sp-trace-id: 6f67ca213a701110
[2025-02-23 14:06:12] [DEBUG] [  library (1522)]     http: curl < Response-Header - x-envoy-upstream-service-time: 17
[2025-02-23 14:06:12] [DEBUG] [  library (1522)]     http: curl < Response-Header - server: envoy
[2025-02-23 14:06:12] [DEBUG] [  library (1522)]     http: curl < Response-Header - strict-transport-security: max-age=31536000
[2025-02-23 14:06:12] [DEBUG] [  library (1522)]     http: curl < Response-Header - x-content-type-options: nosniff
[2025-02-23 14:06:12] [DEBUG] [  library (1522)]     http: curl < Response-Header - via: HTTP/2 edgeproxy, 1.1 google
[2025-02-23 14:06:12] [DEBUG] [  library (1522)]     http: curl < Response-Header - alt-svc: h3=":443"; ma=2592000,h3-29=":443"; ma=2592000
[2025-02-23 14:06:12] [DEBUG] [  library (1522)]     http: curl < Response-Header - 
[2025-02-23 14:06:12] [ SPAM] [  library (1522)]     http: curl < Response-Body
 0000  7b 22 61 63 63 65 73 73 5f 74 6f 6b 65 6e 22 3a  {"access_token":
 0010  22 42 51 41 58 41 35 71 53 4c 73 55 50 79 5a 78  "BQAXA5qSLsUPyZx
 ...

@chme chme requested a review from ejurgensen February 23, 2025 13:33
@ejurgensen
Copy link
Member

Yes, I agree that it would be good to get curl out of the header, and I also think the _new() and _free() for the session would be good.

In general, I think the goal of the logs is to be able to receive data from users to determine what was going on when an issue occured, so that it can be reproduced. They are not for when developing/debugging yourself. So I think logging the contents of every request on debug is too noisy. It's enough to know that OwnTone tried to make a request and the result of that. That's already logged today. On SPAM level I think logging everything is ok, it's spam after all.

I also don't agree with the mutex. The implementation doesn't use any mutable globals as far as I can see, so it's already thread safe. Of course there will be problems if two threads call the function with a reference to the same session, but then it's the caller that should protect with a mutex, not the implementation. I would say it's a standard assumption for any function implementation that the input given by caller isn't going to become invalid during function execution..

I see you also removed "headers_only", since it's not used any more. I think that's fine, but maybe a note about it (removing it since not used any more) in the commit message.

@chme
Copy link
Collaborator Author

chme commented Feb 25, 2025

It's enough to know that OwnTone tried to make a request and the result of that. That's already logged today.

Depends on the kind of error. For connection errors it would be good to have logs for the actual connection attempt.
What do you think about adding a configure flag to enable libcurl logging, similar to the DB_PROFILE flag?

I also don't agree with the mutex. The implementation doesn't use any mutable globals as far as I can see, so it's already thread safe.

Well, the implementation modifies the curl handle (that is an implementation detail for the caller) which in turn makes this call not thread safe. Forcing each caller to guard the call with a mutex, makes the api more difficult to use and results in code duplication.

I would say it's a standard assumption for any function implementation that the input given by caller isn't going to become invalid during function execution.

In this case the implementation makes the the input invalid for other calls for the same session. For example, if libcurl would be replaced by a different library, the method itself might become thread safe. Then all callers should remove the guard with the mutex.

If you insist, I'll move guarding with a mutex to the caller, but in my opinion, it makes more sense to simplify the code and keep the details hidden from the caller.

It might also be worth to have a default session or to at least share the caches:

I see you also removed "headers_only", since it's not used any more. I think that's fine, but maybe a note about it (removing it since not used any more) in the commit message.

Totally forgot, that I removed it ... will update the commit message.

@ejurgensen
Copy link
Member

What do you think about adding a configure flag to enable libcurl logging, similar to the DB_PROFILE flag?

That's fine, but I'm not sure who would be using it? Regular users won't recompile, and I suppose you and me and others who work with the code use either the debugger and/or add ad hoc logging when troubleshooting.

Well, the implementation modifies the curl handle (that is an implementation detail for the caller) which in turn makes this call not thread safe

Many functions modify memory pointed to by an argument, I wouldn't say that makes them not thread safe. By that definition sprintf() or strtok_r() are not thread safe?

Another reason to have the mutex in caller scope is that only the caller can know if locking is actually needed. There is no reason to do any locking for all the regular one-thread/one-off requests. Just like locking for sprintf() would only be needed if two threads both do sprintf(x), which is something the implementation can't know. So I still think it should be moved out of the implementation.

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.

2 participants