TrueTime.now() block UI on InvalidNtpServerResponseException

[tapeo]

Hi! These days, using the TrueTime.now() function, there was a problem concerning the locking of the UI without an actual crash. In fact Android showed the ANR message and the application did not respond to the touch. I initialized truetime with the following function:

AsyncTask.execute(new Runnable() {
                @Override
                public void run() {
                    try {

                            TrueTime.build()
                                    .withNtpHost(TRUETIME_SERVER)
                                    .initialize();

                            Log.e("TrueTime", "Connected");

                    } catch (Exception e) {
                        e.printStackTrace();
                    }
                }
            });

and I run the TrueTime.now().getTime() method every 7 seconds. This is the stacktrace. Any information about it? Thank you!

DALVIK THREADS (15):
"main" prio=5 tid=1 Blocked
  | group="main" sCount=1 dsCount=0 obj=0x73ec9700 self=0xb749b300
  | sysTid=3698 nice=0 cgrp=default sched=0/0 handle=0xb6f1fbec
  | state=S schedstat=( 333721878 8851080 272 ) utm=31 stm=2 core=2 HZ=100
  | stack=0xbe53d000-0xbe53f000 stackSize=8MB
  | held mutexes=
  at truetime.SntpClient.wasInitialized(SntpClient.java:225)
  - waiting to lock <0x01a6f754> (a truetime.SntpClient) held by thread 15
  at truetime.TrueTime.isInitialized(TrueTime.java:44)
  at truetime.TrueTime.now(TrueTime.java:30)
  at com.package.ButtonPresenter.initAnimation(ActivityPresenter.java:135)
  at com.package.ButtonPresenter.<init>(ActivityPresenter.java:83)
  at com.package.ButtonFragment.onCreateView(ButtonView.java:76)
  at android.support.v4.app.Fragment.performCreateView(Fragment.java:2354)
  at android.support.v4.app.FragmentManagerImpl.moveToState(FragmentManager.java:1419)
  at android.support.v4.app.FragmentManagerImpl.moveFragmentToExpectedState(FragmentManager.java:1740)
  at android.support.v4.app.FragmentManagerImpl.moveToState(FragmentManager.java:1809)
  at android.support.v4.app.FragmentManagerImpl.dispatchStateChange(FragmentManager.java:3217)
  at android.support.v4.app.FragmentManagerImpl.dispatchActivityCreated(FragmentManager.java:3171)
  at android.support.v4.app.FragmentController.dispatchActivityCreated(FragmentController.java:192)
  at android.support.v4.app.FragmentActivity.onStart(FragmentActivity.java:560)
  at android.support.v7.app.AppCompatActivity.onStart(AppCompatActivity.java:177)
  at android.app.Instrumentation.callActivityOnStart(Instrumentation.java:1236)
  at android.app.Activity.performStart(Activity.java:6238)
  at android.app.ActivityThread.performLaunchActivity(ActivityThread.java:2307)
  at android.app.ActivityThread.handleLaunchActivity(ActivityThread.java:2407)
  at android.app.ActivityThread.access$800(ActivityThread.java:151)
  at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1319)
  at android.os.Handler.dispatchMessage(Handler.java:102)
  at android.os.Looper.loop(Looper.java:135)
  at android.app.ActivityThread.main(ActivityThread.java:5280)
  at java.lang.reflect.Method.invoke!(Native method)
  at java.lang.reflect.Method.invoke(Method.java:372)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:963)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:758)

04-14 20:43:08.402 1861-1899/com.package W/System.err: .truetime.InvalidNtpServerResponseException: server_response_delay too large for comfort 1452,000000 [actual] >= 200,000000 [expected]
        at .truetime.SntpClient.requestTime(SntpClient.java:182)
        at .truetime.TrueTime.requestTime(TrueTime.java:125)
        at .truetime.TrueTime.initialize(TrueTime.java:121)
        at .truetime.TrueTime.initialize(TrueTime.java:56)
04-14 20:43:08.412 1861-1899/com.package E/trueTimeError: server_response_delay too large for comfort 1452,000000 [actual] >= 200,000000 [expected]
04-14 20:43:44.162 1910-1932/com.package W/System.err:     at .truetime.SntpClient.requestTime(SntpClient.java:121)
        at .truetime.TrueTime.requestTime(TrueTime.java:125)
        at .truetime.TrueTime.initialize(TrueTime.java:121)
        at .truetime.TrueTime.initialize(TrueTime.java:56)
        at .ButtonFragment$7.run(ButtonFragment.java:128)
        at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:231)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
        at java.lang.Thread.run(Thread.java:841)
    Caused by: libcore.io.ErrnoException: recvfrom failed: EAGAIN (Try again)
        at libcore.io.Posix.recvfromBytes(Native Method)
        at libcore.io.Posix.recvfrom(Posix.java:141)
        at libcore.io.BlockGuardOs.recvfrom(BlockGuardOs.java:164)
        at libcore.io.IoBridge.recvfrom(IoBridge.java:506)
        ... 12 more

[mohitrajput987]

I'm too facing the same problem.

[mohitrajput987]

Is there any update on this issue? Today I'm going to remove this library since it hangs the UI sometimes while fetching current time.

[kaushikgopal]

@tapeo + @mohitrajput987 - hmm this does look familiar, I've had a branch for some time where I've been experimenting with some ideas. Can you folks try this branch and tell me if it helps with the issue? https://github.com/instacart/truetime-android/tree/kg/fix/sync_to_atomic

[kaushikgopal]

for context on the Instacart app i've been trying 0aef96c which you can pull from jitpack directly (Note: we use the Rx version which handles a lot of these better).

[kaushikgopal]

master should have this fix. for those eager to take this for a spin try

implementation com.github.instacart.truetime-android:library-extension-rx:09087b6a6e

That should point to the latest commit on master

[simon1867]

@kaushikgopal That fixed the ANR I was getting. I know for me the problem was that the initialize method never finishing on my emulator. When I called TrueTime.now() it would block waiting for the initialize to finish because it calls wasInitialized() on SntpClient which is synchronized.

[kaushikgopal]

👍 thanks for the info @simon-the-canadian. Yeah I don't know what the deal is with emulators. Something has changed recently where it appears like UDP calls don't seem to be going through (this is my guess).

I can raise an issue for this if you think it's something that needs to be addressed, but honestly may not look into it just yet, cause I've basically stopped relying on emulators after they've melted my work machines ><.