@@ -43,6 +43,7 @@ import java.util.concurrent.Semaphore
4343import kotlin.math.max
4444import kotlin.time.Duration
4545import kotlin.time.Duration.Companion.ZERO
46+ import kotlin.time.Duration.Companion.hours
4647import kotlin.time.Duration.Companion.minutes
4748import kotlin.time.Duration.Companion.seconds
4849import kotlin.time.DurationUnit
@@ -444,6 +445,7 @@ class AuthManager(private val cs: CoroutineScope) : Disposable {
444445 autoRefreshWaitingJob?.cancel(CancellationException (message, null ))
445446 autoRefreshJob?.cancel(CancellationException (message, null ))
446447 } catch (e: Throwable ) {
448+ Log .warnWithException(logger, e, " autoRefreshJob failed to stop {}" , e)
447449 ErrorReporter .getInstance().reportError(" AuthManager.stopAutoRefresh" , e)
448450 }
449451 }
@@ -453,6 +455,7 @@ class AuthManager(private val cs: CoroutineScope) : Disposable {
453455 Log .log(logger::trace, " starting autoRefreshJob" )
454456 autoRefreshJob = startAutoRefreshJob(cs)
455457 } catch (e: Throwable ) {
458+ Log .warnWithException(logger, e, " autoRefreshJob failed to start {}" , e)
456459 ErrorReporter .getInstance().reportError(" AuthManager.startAutoRefresh" , e)
457460 }
458461 }
@@ -462,6 +465,7 @@ class AuthManager(private val cs: CoroutineScope) : Disposable {
462465 Log .log(logger::trace, " canceling autoRefreshJob.autoRefreshWaitingJob {}" , message)
463466 autoRefreshWaitingJob?.cancel(CancellationException (message, null ))
464467 } catch (e: Throwable ) {
468+ Log .warnWithException(logger, e, " autoRefreshJob.autoRefreshWaitingJob failed to stop {}" , e)
465469 ErrorReporter .getInstance().reportError(" AuthManager.cancelAutoRefreshWaitingJob" , e)
466470 }
467471 }
@@ -478,6 +482,9 @@ class AuthManager(private val cs: CoroutineScope) : Disposable {
478482 Log .log(logger::trace, " launching autoRefreshJob" )
479483 return cs.launch(CoroutineName (" autoRefreshJob" )) {
480484
485+ var statisticsStartTime = Clock .System .now()
486+ var refreshCounter = 0
487+
481488 Log .log(logger::trace, " ${coroutineContext[CoroutineName ]} auto refresh job started" )
482489 var delay: Duration
483490 while (isActive) {
@@ -507,7 +514,11 @@ class AuthManager(private val cs: CoroutineScope) : Disposable {
507514 delay = 10 .minutes
508515 } else if (credentials == null ) {
509516 // if credentials not found it will probably be created soon
510- Log .log(logger::trace, " ${coroutineContext[CoroutineName ]} credentials for account not found, waiting 1 minute" )
517+ Log .log(
518+ logger::trace,
519+ " ${coroutineContext[CoroutineName ]} credentials for account not found, waiting 1 minute. account {}" ,
520+ account
521+ )
511522 delay = 1 .minutes
512523 } else {
513524 Log .log(logger::trace, " ${coroutineContext[CoroutineName ]} found account and credentials {}" , account)
@@ -518,7 +529,15 @@ class AuthManager(private val cs: CoroutineScope) : Disposable {
518529 (credentials.expirationTime - Clock .System .now().toEpochMilliseconds())
519530 ).toDuration(DurationUnit .MILLISECONDS )
520531
521- if (expireIn <= 1 .minutes) {
532+ if (expireIn == ZERO ) {
533+ // don't refresh if expireIn is zero it will e refreshed on authentication exception
534+ Log .log(
535+ logger::trace,
536+ " ${coroutineContext[CoroutineName ]} credentials expires in zero seconds,not refreshing, waiting 5 minutes. account {}" ,
537+ account
538+ )
539+ delay = 5 .minutes
540+ } else if (expireIn <= 1 .minutes) {
522541 Log .log(
523542 logger::trace,
524543 " ${coroutineContext[CoroutineName ]} credentials expires in {} , refreshing account {}" ,
@@ -533,23 +552,62 @@ class AuthManager(private val cs: CoroutineScope) : Disposable {
533552 false
534553 }
535554
555+ refreshCounter++
556+
557+
558+ // Detect errors and send statistics
559+ val now = Clock .System .now()
560+ val timeSinceLastStatistics = (now - statisticsStartTime).inWholeMilliseconds.toDuration(DurationUnit .MILLISECONDS )
561+
562+ // detect too many refresh in a short time. in correct functioning there should never be more than 5 refresh in 1 hour
563+ if (refreshCounter > 5 && timeSinceLastStatistics < 1 .hours) {
564+ ErrorReporter .getInstance().reportError(
565+ " AuthManager.autoRefreshJob" , " too many refresh" , mapOf (
566+ " period.minutes" to timeSinceLastStatistics.inWholeMinutes,
567+ " refresh.counter" to refreshCounter
568+ )
569+ )
570+ }
571+
572+ // send statistics approximately every 1 hour , this will help detect incorrect functioning on this job.
573+ if (timeSinceLastStatistics >= 1 .hours) {
574+ statisticsStartTime = now
575+ reportAuthPosthogEvent(
576+ " AutoRefreshStatistics" , " AutoRefreshJob" , null , mapOf (
577+ " period.minutes" to timeSinceLastStatistics.inWholeMinutes,
578+ " refresh.counter" to refreshCounter
579+ )
580+ )
581+ refreshCounter = 0
582+ }
583+
536584 if (refreshSuccess) {
537585 fireChange()
538- Log .log(logger::trace, " ${coroutineContext[CoroutineName ]} credentials for account refreshed {}" , account)
539- // immediately loop again and compute the next delay
540- delay = ZERO
586+ Log .log(
587+ logger::trace,
588+ " ${coroutineContext[CoroutineName ]} credentials for account refreshed,waiting 5 minutes. account {}" ,
589+ account
590+ )
591+ // after successful refresh wait 5 minutes , the token should be valid for 15 minutes
592+ // it should also let the credential store save and refresh its caches if any.
593+ delay = 5 .minutes
541594 } else {
542- Log .log(logger::trace, " ${coroutineContext[CoroutineName ]} refresh failed, waiting 5 minutes" )
595+ Log .log(
596+ logger::trace,
597+ " ${coroutineContext[CoroutineName ]} refresh failed, waiting 5 minutes. account {}" ,
598+ account
599+ )
543600 delay = 5 .minutes
544601 }
545602 } else {
546603 delay =
547604 max(0L , (expireIn.inWholeMilliseconds - 1 .minutes.inWholeMilliseconds)).toDuration(DurationUnit .MILLISECONDS )
548605 Log .log(
549606 logger::trace,
550- " ${coroutineContext[CoroutineName ]} credentials for account expires in {}, waiting {}" ,
607+ " ${coroutineContext[CoroutineName ]} credentials for account expires in {}, waiting {}. account {} " ,
551608 expireIn,
552- delay
609+ delay,
610+ account
553611 )
554612 }
555613 }
@@ -573,6 +631,7 @@ class AuthManager(private val cs: CoroutineScope) : Disposable {
573631 }
574632
575633 } catch (e: CancellationException ) {
634+ Log .log(logger::trace, " ${coroutineContext[CoroutineName ]} got CancellationException {}" , e)
576635 throw e
577636 } catch (e: Throwable ) {
578637 Log .warnWithException(logger, e, " ${coroutineContext[CoroutineName ]} error in autoRefreshJob" )
@@ -581,7 +640,10 @@ class AuthManager(private val cs: CoroutineScope) : Disposable {
581640 }
582641 }
583642
584- Log .log(logger::trace, " job autoRefreshJob exited (this should happen on IDE shutdown or when replacing api client)" )
643+ Log .log(
644+ logger::trace,
645+ " ${coroutineContext[CoroutineName ]} job autoRefreshJob exited (this should happen on IDE shutdown or when replacing api client)"
646+ )
585647 }
586648 }
587649
0 commit comments