WMS-DEV / usos4j

Java client for USOS API
MIT License
24 stars 0 forks source link

Missing `logback core` on Android #18

Closed qamarq closed 1 month ago

qamarq commented 1 month ago

Hey, another mistake I believe. While fetching user data with UsosUser user = usos.getUserApi(accessToken).users().user(); I'm getting error in logcat:

= Verifying access token key
2024-10-08 11:54:48.102  5298-5332  AndroidRuntime          com.qamarq.betterusos                E  FATAL EXCEPTION: pool-2-thread-1 (Ask Gemini)
                                                                                                    Process: com.qamarq.betterusos, PID: 5298
                                                                                                    java.lang.NoSuchMethodError: No virtual method getModule()Ljava/lang/Module; in class Ljava/lang/Class; or its super classes (declaration of 'java.lang.Class' appears in /apex/com.android.art/javalib/core-oj.jar)
                                                                                                        at ch.qos.logback.core.util.EnvUtil.logbackVersionByModule(EnvUtil.java:56)
                                                                                                        at ch.qos.logback.core.util.EnvUtil.logbackVersion(EnvUtil.java:36)
                                                                                                        at ch.qos.logback.classic.util.ContextInitializer.autoConfig(ContextInitializer.java:75)
                                                                                                        at ch.qos.logback.classic.util.ContextInitializer.autoConfig(ContextInitializer.java:66)
                                                                                                        at ch.qos.logback.classic.spi.LogbackServiceProvider.initializeLoggerContext(LogbackServiceProvider.java:52)
                                                                                                        at ch.qos.logback.classic.spi.LogbackServiceProvider.initialize(LogbackServiceProvider.java:41)
                                                                                                        at org.slf4j.LoggerFactory.bind(LoggerFactory.java:196)

I think it's cause by not existing logback core on android. It should be logback-android I guess. Any tips? Or I'm wrong

gniadeck commented 1 month ago

hi, unfortunately we were designing our library with pure java mindset, so we won't be able to add logback-android dependency to the project. We also wouldn't like to create any project like usos4j-android, as we don't have capacity to maintain it for now.

However, since we are using Slf4j without any custom configuration, I think you might be able to simply add the dependency to logback-android in the project, and it should use android-enhanced version of logback. Let us know if it helped :)

qamarq commented 1 month ago

hi @gniadeck , unfortunately after exluding logback-classic and import logback-android lib throw errors:

Process: com.qamarq.betterusos, PID: 31053
java.lang.NoClassDefFoundError: Failed resolution of: Lorg/slf4j/LoggerFactory;
    at pl.wmsdev.usos4j.client.UsosServerAPIDefinition.<clinit>(UsosServerAPIDefinition.java:12)
    at pl.wmsdev.usos4j.client.Usos.getUserApi(Usos.java:83)
    at com.qamarq.betterusos.MainActivity.lambda$verifyAccessTokens$1(MainActivity.java:166)
    at com.qamarq.betterusos.MainActivity.$r8$lambda$21OfpG7FE4GRDoCi5EliuQmBE60(Unknown Source:0)
    at com.qamarq.betterusos.MainActivity$$ExternalSyntheticLambda1.run(D8$$SyntheticClass:0)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:644)
    at java.lang.Thread.run(Thread.java:1012)
Caused by: java.lang.ClassNotFoundException: Didn't find class "org.slf4j.LoggerFactory" on path: DexPathList[[dex file "/data/data/com.qamarq.betterusos/code_cache/.overlay/base.apk/classes.dex", dex file "/data/data/com.qamarq.betterusos/code_cache/.overlay/base.apk/classes3.dex", dex file "/data/data/com.qamarq.betterusos/code_cache/.overlay/base.apk/classes5.dex", dex file "/data/data/com.qamarq.betterusos/code_cache/.overlay/base.apk/classes6.dex", zip file "/data/app/~~TQfmxr__cV7GXD4VMmlFiA==/com.qamarq.betterusos-7RNFSjfcOr3a9mpBWj0B7w==/base.apk"],nativeLibraryDirectories=[/data/app/~~TQfmxr__cV7GXD4VMmlFiA==/com.qamarq.betterusos-7RNFSjfcOr3a9mpBWj0B7w==/lib/arm64, /system/lib64, /system_ext/lib64]]
    at dalvik.system.BaseDexClassLoader.findClass(BaseDexClassLoader.java:259

Is there any way to add an option, for example, when debugging is disabled, so that it doesn't use this library at all? I really want to use your library. My current gradle:

implementation(libs.usos4j) {
        exclude(group = "ch.qos.logback", module = "logback-classic")
    }
    implementation(libs.logback.android)
gniadeck commented 1 month ago

thanks for providing more details on the issue, we'd like to solve such problems, so usos4j can be used on as many platforms as possible :)

unfortunately we are not able to implement logging in such way at the moment, and we would probably have to resign from using Slf4j lombok's annotation, or do some nasty hacks with class shadowing.

did you try to add dependency to slf4j-api to the project? logback-classic depends on it out of the box, while i'm not sure if logback-android does, and it looks like the error you mentioned is connected with one of the Slf4j's classes. If this won't work you can try simply depending only on slf4j-api, without logback-android, as it provides some basic NOP implementation :)

logback-android's documentation also mentions the need to add slf4j-api to the classpath

qamarq commented 1 month ago

okaay, now its working but there is another, very wierd error. while calling

UsosUser user = usos.getUserApi(accessToken).users().user();
System.out.println("= User: " + user.firstName() + " " + user.lastName());

I'm having response error: = Error: Error while deserializing JSON: {"id": "608975", "last_name": "Marczak", "middle_names"... I copied JSON to another code editor and it's all correct wihout errors. So why it's "Error while deserializing JSON" error even exist? What can cause it?

gniadeck commented 1 month ago

There might have been some changes in USOS API that were not reflected in the library code, would you mind sharing the whole error message? Of course anonymize the data, i'm just interested in what exactly caused the error :)

qamarq commented 1 month ago

This is my code from try|catch:

} catch (Exception e) {
    System.out.println("= Error: " + e.getMessage());
    Snackbar.make(findViewById(R.id.main), "Błąd podczas autoryzacji", Snackbar.LENGTH_LONG).show();
}

And this is entire log line:

2024-10-08 19:57:46.316 19571-19664 System.out              com.qamarq.betterusos                I  = Error: Error while deserializing JSON: {"id": "1", "last_name": "Marczak", "middle_names": "A", "first_name": "Kamil", "previous_names": [], "titles": {"before": null, "after": null}, "student_status": 2, "staff_status": 0, "phd_student_status": 0, "external_ids": {}, "homepage_url": null, "profile_url": "https://web.usos.pwr.edu.pl/kontroler.php?_action=...", "sex": "M", "email": null, "email_access": "plaintext", "alt_email": null, "email_url": "https://web.usos.pwr.edu.pl/kontroler.php?_action=...", "has_email": true, "pesel": null, "birth_date": null, "citizenship": null, "revenue_office_id": null, "student_number": "123456", "phone_numbers": [], "office_hours": {"pl": "", "en": ""}, "interests": {"pl": "", "en": ""}, "room": null, "employment_functions": [], "employment_positions": [], "student_programmes": [{"id": "107253", "programme": {"id": "W04-ISTP-000P-OSIW7", "description": {"pl": "informatyka stosowana, pierwszego stopnia, stacjonarne", "en": "Applied Computer Science, first-level studies, full-time studies"}}}], "has_photo": true, "photo_urls": {"50x50": "https://apps.usos.pwr.edu.pl/res/up/50x50/..."}, "mobile_numbers": [], "course_editions_conducted": [], "postal_addresses": [], "library_card_id": null}
qamarq commented 1 month ago

Okay, it's actually this line: UsosUser user = usos.getUserApi(accessToken).users().user();

so I can't even parse JSON on my own. my code:

Log.i("app", "starting getting");
                UsosUser user = usos.getUserApi(accessToken).users().user();
                Log.i("app", "finished getting");

and error logs:

starting getting
2024-10-08 20:23:37.640 27883-27905 HWUI                    com.qamarq.betterusos                D  endAllActiveAnimators on 0xb4000074d8a06ed0 (RippleDrawable) with handle 0xb4000074a89eec10
2024-10-08 20:23:37.697 27883-27954 System.out              com.qamarq.betterusos                I  = Error: Error while deserializing JSON: {...}
2024-10-08 20:23:38.116 27883-27883 WindowOnBackDispatcher  com.qamarq.betterusos                W  sendCancelIfRunning: isInProgress=falsecallback=android.view.ViewRootImpl$$ExternalSyntheticLambda11@f753931
2024-10-08 20:23:38.738 27883-27987 ProfileInstaller        com.qamarq.betterusos                D  Installing profile for com.qamarq.betterusos
2024-10-08 20:23:58.042 27883-27889 marq.betterusos         com.qamarq.betterusos                W  Cleared Reference was only reachable from finalizer (only reported once)
gniadeck commented 1 month ago

Thanks for the details, are you running our library on Java 17 or higher? Unfortunately the error message here can and will be improved, as the root cause of the error is simply logged in debug and ignored. I also tried to deserialize provided JSON by myself to UsosUser object, and didn't notice any issues, which makes me think it's something related to the runtime.

If bumping Java version won't work, would you be able to turn on debug logging in logback, or use the debugger, to stop at a breakpoint in UsosDeserializationUtils::deserialize in catch statement, and send more information regarding JsonProcessingException that is being thrown here?

    public static <T> T deserialize(String json, Class<T> clazz) {
        try {
            return mapper.readValue(json, clazz);
        } catch (JsonProcessingException e) {
            log.debug(e.toString());
            throw new Usos4jException("Error while deserializing JSON: %s".formatted(json), e);
        }
    }

This way we could gather more information on the error you encountered, as i can't really help you without more details or reproduction :(

qamarq commented 1 month ago

I'm using JAVA 17:

compileOptions {
        sourceCompatibility = JavaVersion.VERSION_17
        targetCompatibility = JavaVersion.VERSION_17
    }

My code:

System.out.println("= Pin: " + pin);
                System.out.println("= Token: " + token.toFrameworkToken().getToken());

                UsosAccessToken accessToken = usos.getAccessToken(token, pin);
                System.out.println("= Success");

                String accessTokenKey = accessToken.toFrameworkToken().getToken();
                String accessTokenSecret = accessToken.toFrameworkToken().getTokenSecret();

                System.out.println("= Access token: " + accessTokenKey);
                System.out.println("= Access token secret: " + accessTokenSecret);

                SharedPreferences sharedPreferences = getSharedPreferences("user", MODE_PRIVATE);
                SharedPreferences.Editor editor = sharedPreferences.edit();
                editor.putString("access_token_key", accessTokenKey);
                editor.putString("access_token_secret", accessTokenSecret);

                editor.remove("request_token_key");
                editor.remove("request_token_secret");
                editor.apply();

                UsosUser user = usos.getUserApi(accessToken).users().user();
                System.out.println("= User: " + user.firstName() + " " + user.lastName());

And logs:

2024-10-08 21:18:41.379  9613-10044 System.out              com.qamarq.betterusos                I  = Pin: 58078652
2024-10-08 21:18:41.379  9613-10044 System.out              com.qamarq.betterusos                I  = Token: XYFFQV2zBVGgeqvTG3j9
2024-10-08 21:18:41.379  9613-10044 System.out              com.qamarq.betterusos                I  obtaining access token from https://apps.usos.pwr.edu.pl/services/oauth/access_token
2024-10-08 21:18:41.379  9613-10044 System.out              com.qamarq.betterusos                I  setting token to: com.github.scribejava.core.model.OAuth1RequestToken@42dcf56d and verifier to: 58078652
2024-10-08 21:18:41.379  9613-10044 System.out              com.qamarq.betterusos                I  generating signature...
2024-10-08 21:18:41.382  9613-10044 System.out              com.qamarq.betterusos                I  base string is: POST&https%3A%2F%2Fapps.usos.pwr.edu.pl%2Fservices%2Foauth%2Faccess_token&oauth_consumer_key%3DsP8KGVz45DYZ27nFtbLh%26oauth_nonce%3D3638863235%26oauth_signature_method%3DHMAC-SHA1%26oauth_timestamp%3D1728415121%26oauth_token%3DXYFFQV2zBVGgeqvTG3j9%26oauth_verifier%3D58078652%26oauth_version%3D1.0
2024-10-08 21:18:41.382  9613-10044 System.out              com.qamarq.betterusos                I  signature is: lqtGFoD9ojhaDui3m7czCIl/Vt0=
2024-10-08 21:18:41.382  9613-10044 System.out              com.qamarq.betterusos                I  appended additional OAuth parameters: {oauth_verifier=58078652, oauth_nonce=3638863235, oauth_signature=lqtGFoD9ojhaDui3m7czCIl/Vt0=, oauth_token=XYFFQV2zBVGgeqvTG3j9, oauth_consumer_key=sP8KGVz45DYZ27nFtbLh, oauth_timestamp=1728415121, oauth_signature_method=HMAC-SHA1, oauth_version=1.0}
2024-10-08 21:18:41.383  9613-10044 System.out              com.qamarq.betterusos                I  using Http Header signature
2024-10-08 21:18:41.389  9613-9613  ContentCaptureHelper    com.qamarq.betterusos                I  Setting logging level to OFF
2024-10-08 21:18:41.419  9613-10044 System.out              com.qamarq.betterusos                I  = Success
2024-10-08 21:18:41.419  9613-10044 System.out              com.qamarq.betterusos                I  = Access token: NAunfNnexqKLRrMrL4pJ
2024-10-08 21:18:41.419  9613-10044 System.out              com.qamarq.betterusos                I  = Access token secret: Fcs...
2024-10-08 21:18:41.419  9613-10044 System.out              com.qamarq.betterusos                I  signing request: https://apps.usos.pwr.edu.pl/services/users/user?fields=id|first_name|middle_names|last_name|previous_names|sex|titles|student_status|staff_status|email_access|email|email_url|has_email|homepage_url|profile_url|phone_numbers|mobile_numbers|office_hours|interests|has_photo|photo_urls|student_number|pesel|birth_date|revenue_office_id|citizenship|room|student_programmes|employment_functions|employment_positions|course_editions_conducted|postal_addresses|alt_email|external_ids|phd_student_status|library_card_id
2024-10-08 21:18:41.420  9613-10044 System.out              com.qamarq.betterusos                I  setting token to: com.github.scribejava.core.model.OAuth1AccessToken@133d40d3
2024-10-08 21:18:41.421  9613-10044 System.out              com.qamarq.betterusos                I  generating signature...
2024-10-08 21:18:41.423  9613-10044 System.out              com.qamarq.betterusos                I  base string is: GET&https%3A%2F%2Fapps.usos.pwr.edu.pl%2Fservices%2Fusers%2Fuser&fields%3Did%257Cfirst_name%257Cmiddle_names%257Clast_name%257Cprevious_names%257Csex%257Ctitles%257Cstudent_status%257Cstaff_status%257Cemail_access%257Cemail%257Cemail_url%257Chas_email%257Chomepage_url%257Cprofile_url%257Cphone_numbers%257Cmobile_numbers%257Coffice_hours%257Cinterests%257Chas_photo%257Cphoto_urls%257Cstudent_number%257Cpesel%257Cbirth_date%257Crevenue_office_id%257Ccitizenship%257Croom%257Cstudent_programmes%257Cemployment_functions%257Cemployment_positions%257Ccourse_editions_conducted%257Cpostal_addresses%257Calt_email%257Cexternal_ids%257Cphd_student_status%257Clibrary_card_id%26oauth_consumer_key%3DsP8KGVz45DYZ27nFtbLh%26oauth_nonce%3D2761932768%26oauth_signature_method%3DHMAC-SHA1%26oauth_timestamp%3D1728415121%26oauth_token%3DNAunfNnexqKLRrMrL4pJ%26oauth_version%3D1.0
2024-10-08 21:18:41.423  9613-10044 System.out              com.qamarq.betterusos                I  signature is: lO6TlAVrOm/ZdlXCzOgSc70pERo=
2024-10-08 21:18:41.423  9613-10044 System.out              com.qamarq.betterusos                I  appended additional OAuth parameters: {oauth_nonce=2761932768, oauth_signature=lO6TlAVrOm/ZdlXCzOgSc70pERo=, oauth_token=NAunfNnexqKLRrMrL4pJ, oauth_consumer_key=sP8KGVz45DYZ27nFtbLh, oauth_timestamp=1728415121, oauth_signature_method=HMAC-SHA1, oauth_version=1.0}
2024-10-08 21:18:41.423  9613-10044 System.out              com.qamarq.betterusos                I  using Http Header signature
2024-10-08 21:18:41.514  9613-10044 System.out              com.qamarq.betterusos                I  = Error: Error while deserializing JSON: {}
gniadeck commented 1 month ago

Thanks for the logs, unfortunately they aren't enough for me to debug the issue. I released version 1.1.5 to maven central with improved logs. Can you try bumping the version and sending the logs again?

qamarq commented 1 month ago

updated code:

System.out.println("= Error: " + e.getMessage());
System.out.println("= Error: " + e.getCause());
System.out.println("= Error: " + e);

and logs:

2024-10-08 22:59:43.182  8589-8770  System.out              com.qamarq.betterusos                I  = Error: Error while deserializing JSON: {...}
2024-10-08 22:59:43.182  8589-8770  System.out              com.qamarq.betterusos                I  = Error: com.fasterxml.jackson.databind.exc.InvalidDefinitionException: Cannot construct instance of `pl.wmsdev.usos4j.model.user.UsosUser` (no Creators, like default constructor, exist): cannot deserialize from Object value (no delegate- or property-based Creator)
2024-10-08 22:59:43.182  8589-8770  System.out              com.qamarq.betterusos                I   at [Source: (String)"{...}
2024-10-08 22:59:43.182  8589-8770  System.out              com.qamarq.betterusos                I  = Error: pl.wmsdev.usos4j.model.exceptions.Usos4jException: Error while deserializing JSON: {...}

If u need something more, tell me. And how achieve that

gniadeck commented 1 month ago

thanks, all of our classes that we deserialize to, should contain a proper constructor that jackson can deserialize objects with, and the same story is with UsosUser. I can't reproduce this issue on vanilla Java locally, but since we use records, do you think it might be connected with this issue?

Try adding this dependency to your pom.xml :)

       <dependency>
            <groupId>com.fasterxml.jackson.module</groupId>
            <artifactId>jackson-module-android-record</artifactId>
            <version>2.18.0</version>
        </dependency>
qamarq commented 1 month ago

Okay, don't know how, but it works just as expected. Many thanks, this is my final android gradle (kts) to work with usos4j:

{
    implementation("pl.wmsdev:usos4j:1.1.5") {
        exclude(group = "ch.qos.logback", module = "logback-classic")
    }
    implementation(libs.logback.android)
    implementation(libs.slf4j.api)
    implementation(libs.jackson.module.android.record)
}