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.

Sign up for GitHub

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

Enhanced exceptions #1077

Merged
merged 6 commits into from
Aug 16, 2020
Merged

Enhanced exceptions #1077

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
969559f
stack trace manipulation
Aug 11, 2020
e032a7b
reverse printFiberTrace order
Aug 12, 2020
be33127
configuration and augmentException
Aug 12, 2020
ccedb18
Documentation
Aug 12, 2020
a7a0e4e
address pr feedback
Aug 14, 2020
dd2f605
IOContext null check
Aug 14, 2020
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 2 additions & 0 deletions core/js/src/main/scala/cats/effect/internals/TracingPlatform.scala
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -24,4 +24,6 @@ object TracingPlatform {
final val isStackTracing: Boolean = isFullStackTracing || isCachedStackTracing

final val traceBufferSize: Int = 32

final val enhancedExceptions: Boolean = false
}
12 changes: 11 additions & 1 deletion core/jvm/src/main/java/cats/effect/internals/TracingPlatform.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -58,6 +58,16 @@ public final class TracingPlatform {
return Optional.empty();
}
})
.orElse(128);
.orElse(16);

/**
* Sets the enhanced exceptions flag, which controls whether or not the
* stack traces of IO exceptions are augmented to include async stack trace information.
* Stack tracing must be enabled in order to use this feature.
* This flag is enabled by default.
*/
public static final boolean enhancedExceptions = Optional.ofNullable(System.getProperty("cats.effect.enhancedExceptions"))
.map(x -> Boolean.valueOf(x))
.orElse(true);

}
3 changes: 3 additions & 0 deletions core/shared/src/main/scala/cats/effect/internals/IOContext.scala
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -38,4 +38,7 @@ final private[effect] class IOContext() {
def trace(): IOTrace =
IOTrace(events.toList, captured, omitted)

def getStackTraces(): List[IOEvent.StackTrace] =
events.toList.collect { case ev: IOEvent.StackTrace => ev }

}
47 changes: 45 additions & 2 deletions core/shared/src/main/scala/cats/effect/internals/IORunLoop.scala
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -18,8 +18,8 @@ package cats.effect.internals

import cats.effect.IO
import cats.effect.IO.{Async, Bind, ContextSwitch, Delay, Map, Pure, RaiseError, Suspend, Trace}
import cats.effect.tracing.IOEvent
import cats.effect.internals.TracingPlatform.isStackTracing
import cats.effect.tracing.{IOEvent, IOTrace}
import cats.effect.internals.TracingPlatform.{enhancedExceptions, isStackTracing}

import scala.util.control.NonFatal

Expand Down Expand Up @@ -114,6 +114,9 @@ private[effect] object IORunLoop {
catch { case NonFatal(ex) => RaiseError(ex) }

case RaiseError(ex) =>
if (isStackTracing && enhancedExceptions && ctx != null) {
augmentException(ex, ctx)
}
findErrorHandler(bFirst, bRest) match {
case null =>
cb(Left(ex))
Expand Down Expand Up @@ -244,6 +247,9 @@ private[effect] object IORunLoop {
} catch { case NonFatal(ex) => RaiseError(ex) }

case RaiseError(ex) =>
if (isStackTracing && enhancedExceptions && ctx != null) {
augmentException(ex, ctx)
}
findErrorHandler(bFirst, bRest) match {
case null =>
return currentIO.asInstanceOf[IO[A]]
Expand Down Expand Up @@ -357,6 +363,43 @@ private[effect] object IORunLoop {
}
}

/**
* If stack tracing and contextual exceptions are enabled, this
* function will rewrite the stack trace of a captured exception
* to include the async stack trace.
*/
private def augmentException(ex: Throwable, ctx: IOContext): Unit = {
val stackTrace = ex.getStackTrace
Copy link
Author

Choose a reason for hiding this comment

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

We will throw a NPE here if ex is null. I think that would break existing code that happen to rely on this behavior

Copy link
Member

@djspiewak djspiewak Aug 14, 2020 •
edited
Loading

Choose a reason for hiding this comment

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

Do people actually run raiseError(null)? I think I'm pretty comfortable telling those people that they just have to turn off augmented exceptions, because they don't deserve nice things. :-P

if (!stackTrace.isEmpty) {
val augmented = stackTrace(stackTrace.length - 1) eq augmentationMarker
Copy link
Author

@RaasAhsan RaasAhsan Aug 14, 2020 •
edited
Loading

Choose a reason for hiding this comment

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

So the idea here is that a reference equality is probably a lot faster than substring searches. After we augment an exception, we append the augmentation marker which can be used for comparison later. Notice that because it is declared private, callers can't access it and therefore they can't accidentally insert a marker.

The consequence of this is that printed stack traces show the marker at the end. I verified that we can't insert null as a marker.

java.lang.Throwable: hello world!
	at org.simpleapp.examples.Main$.b(Main.scala:29)
	at org.simpleapp.examples.Main$.a(Main.scala:26)
	at org.simpleapp.examples.Main$.$anonfun$foo$11(Main.scala:39)
	at main$ @ org.simpleapp.examples.Main$.main(Main.scala:23)
	at map @ org.simpleapp.examples.Main$.$anonfun$foo$10(Main.scala:39)
	at flatMap @ org.simpleapp.examples.Main$.$anonfun$foo$8(Main.scala:37)
	at flatMap @ org.simpleapp.examples.Main$.$anonfun$foo$6(Main.scala:36)
	at flatMap @ org.simpleapp.examples.Main$.$anonfun$foo$4(Main.scala:35)
	at flatMap @ org.simpleapp.examples.Main$.$anonfun$foo$2(Main.scala:34)
	at flatMap @ org.simpleapp.examples.Main$.foo(Main.scala:33)
	at flatMap @ org.simpleapp.examples.Main$.program(Main.scala:44)
	at as @ org.simpleapp.examples.Main$.run(Main.scala:50)
	at main$ @ org.simpleapp.examples.Main$.main(Main.scala:23)
	at .(:0)

We're also doing a lot of Array and List manipulation here. Without thinking about it more, I'm not sure what the most efficient approach is (do everything in Array or List, and when should we convert back to an array?).

I'll benchmark this tomorrow so we have a concrete answer.

Copy link
Author

Choose a reason for hiding this comment

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

I just realized that users can access an instance of the market, through the stack trace itself! I don't think it'll be a problem either way because they would have to be deliberately manipulating stack traces for something to mess up. Same deal with checking @ probably.

Copy link
Member

Choose a reason for hiding this comment

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

So the idea here is that a reference equality is probably a lot faster than substring searches. After we augment an exception, we append the augmentation marker which can be used for comparison later. Notice that because it is declared private, callers can't access it and therefore they can't accidentally insert a marker.

Hmm, I think this is worth benchmarking. In my experience, indexOf is really really fast, so I don't think there'll be that much of a difference, but I could be mistaken!

if (!augmented) {
val prefix = dropRunLoopFrames(stackTrace)
val suffix = ctx
.getStackTraces()
.flatMap(t => IOTrace.getOpAndCallSite(t.stackTrace))
.map {
case (methodSite, callSite) =>
new StackTraceElement(methodSite.getMethodName + " @ " + callSite.getClassName,
callSite.getMethodName,
callSite.getFileName,
callSite.getLineNumber)
}
.toArray
ex.setStackTrace(prefix ++ suffix ++ Array(augmentationMarker))
}
}
}

private def dropRunLoopFrames(frames: Array[StackTraceElement]): Array[StackTraceElement] =
frames.takeWhile(ste => !runLoopFilter.exists(ste.getClassName.startsWith(_)))

private[this] val runLoopFilter = List(
"cats.effect.",
"scala."
)

private[this] val augmentationMarker = new StackTraceElement("", "", "", 0)

/**
* A `RestartCallback` gets created only once, per [[startCancelable]]
* (`unsafeRunAsync`) invocation, once an `Async` state is hit,
Expand Down
2 changes: 1 addition & 1 deletion core/shared/src/main/scala/cats/effect/internals/IOTracing.scala
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -45,7 +45,7 @@ private[effect] object IOTracing {
}

private def buildFrame(): IOEvent =
IOEvent.StackTrace(new Throwable())
IOEvent.StackTrace(new Throwable().getStackTrace.toList)

/**
* Global cache for trace frames. Keys are references to lambda classes.
Expand Down
7 changes: 4 additions & 3 deletions core/shared/src/main/scala/cats/effect/internals/RingBuffer.scala
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -46,10 +46,11 @@ final private[internals] class RingBuffer[A <: AnyRef](size: Int) {
def capacity: Int =
length

// returns a list in reverse order of insertion
def toList: List[A] = {
val end = index
val start = Math.max(end - length, 0)
(start until end).toList
val start = index - 1
RaasAhsan marked this conversation as resolved.
Show resolved Hide resolved
val end = Math.max(index - length, 0)
(start to end by -1).toList
.map(i => array(i & mask).asInstanceOf[A])
}

Expand Down
5 changes: 1 addition & 4 deletions core/shared/src/main/scala/cats/effect/tracing/IOEvent.scala
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -20,9 +20,6 @@ sealed abstract class IOEvent

object IOEvent {

final case class StackTrace(throwable: Throwable) extends IOEvent {
def stackTrace: List[StackTraceElement] =
throwable.getStackTrace().toList
}
final case class StackTrace(stackTrace: List[StackTraceElement]) extends IOEvent

}
60 changes: 32 additions & 28 deletions core/shared/src/main/scala/cats/effect/tracing/IOTrace.scala
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -33,11 +33,11 @@ final case class IOTrace(events: List[IOEvent], captured: Int, omitted: Int) {
val Junction = "├"
val Line = "│"

val acc0 = s"IOTrace: $captured frames captured\n"
Copy link
Author

Choose a reason for hiding this comment

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

I'm going to reorganize this code and come up with better names.

if (options.showFullStackTraces) {
val stackTraces = events.collect { case e: IOEvent.StackTrace => e }

val header = s"IOTrace: $captured frames captured, $omitted omitted\n"
val body = stackTraces.zipWithIndex
val acc1 = stackTraces.zipWithIndex
.map {
case (st, index) =>
val tag = getOpAndCallSite(st.stackTrace)
Expand All @@ -62,56 +62,44 @@ final case class IOTrace(events: List[IOEvent], captured: Int, omitted: Int) {
}
.mkString("\n")

header + body
val acc2 = if (omitted > 0) {
"\n" + TurnRight + s" ... ($omitted frames omitted)\n"
} else "\n" + TurnRight + "\n"

acc0 + acc1 + acc2
} else {
val acc0 = s"IOTrace: $captured frames captured, $omitted omitted\n"
val acc1 = events.zipWithIndex
.map {
case (event, index) =>
val junc = if (index == events.length - 1) TurnRight else Junction
val junc = if (index == events.length - 1 && omitted == 0) TurnRight else Junction
val message = event match {
case ev: IOEvent.StackTrace => {
getOpAndCallSite(ev.stackTrace)
.map {
case (methodSite, callSite) =>
val loc = renderStackTraceElement(callSite)
val op = NameTransformer.decode(methodSite.getMethodName)
s"$op at $loc"
s"$op @ $loc"
}
.getOrElse("(...)")
}
}
s" $junc $message"
}
.mkString(acc0, "\n", "\n")
.mkString(acc0, "\n", "")

val acc2 = if (omitted > 0) {
acc1 + "\n " + TurnRight + s" ... ($omitted frames omitted)"
RaasAhsan marked this conversation as resolved.
Show resolved Hide resolved
} else acc1

acc1
acc2 + "\n"
}
}
}

private[effect] object IOTrace {

// Number of lines to drop from the top of the stack trace
def stackTraceIgnoreLines = 3

private[this] val anonfunRegex = "^\\$+anonfun\\$+(.+)\\$+\\d+$".r

private[this] val stackTraceFilter = List(
"cats.effect.",
"cats.",
"sbt.",
"java.",
"sun.",
"scala."
)

private def renderStackTraceElement(ste: StackTraceElement): String = {
val methodName = demangleMethod(ste.getMethodName)
s"${ste.getClassName}.$methodName (${ste.getFileName}:${ste.getLineNumber})"
}

private def getOpAndCallSite(frames: List[StackTraceElement]): Option[(StackTraceElement, StackTraceElement)] =
def getOpAndCallSite(frames: List[StackTraceElement]): Option[(StackTraceElement, StackTraceElement)] =
frames
.sliding(2)
.collect {
Expand All @@ -121,9 +109,25 @@ private[effect] object IOTrace {
case (_, callSite) => !stackTraceFilter.exists(callSite.getClassName.startsWith(_))
}

private def renderStackTraceElement(ste: StackTraceElement): String = {
val methodName = demangleMethod(ste.getMethodName)
s"${ste.getClassName}.$methodName (${ste.getFileName}:${ste.getLineNumber})"
}

private def demangleMethod(methodName: String): String =
anonfunRegex.findFirstMatchIn(methodName) match {
case Some(mat) => mat.group(1)
case None => methodName
}

private[this] val anonfunRegex = "^\\$+anonfun\\$+(.+)\\$+\\d+$".r

private[this] val stackTraceFilter = List(
"cats.effect.",
"cats.",
"sbt.",
"java.",
"sun.",
"scala."
)
}
8 changes: 4 additions & 4 deletions core/shared/src/test/scala/cats/effect/internals/IOContextTests.scala
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -23,13 +23,13 @@ import org.scalatest.funsuite.AnyFunSuite
class IOContextTests extends AnyFunSuite with Matchers {

val traceBufferSize: Int = cats.effect.internals.TracingPlatform.traceBufferSize
val throwable = new Throwable()
val stackTrace = new Throwable().getStackTrace.toList

test("push traces") {
val ctx = new IOContext()

val t1 = IOEvent.StackTrace(throwable)
val t2 = IOEvent.StackTrace(throwable)
val t1 = IOEvent.StackTrace(stackTrace)
val t2 = IOEvent.StackTrace(stackTrace)

ctx.pushEvent(t1)
ctx.pushEvent(t2)
Expand All @@ -44,7 +44,7 @@ class IOContextTests extends AnyFunSuite with Matchers {
val ctx = new IOContext()

for (_ <- 0 until (traceBufferSize + 10)) {
ctx.pushEvent(IOEvent.StackTrace(throwable))
ctx.pushEvent(IOEvent.StackTrace(stackTrace))
}

val trace = ctx.trace()
Expand Down
4 changes: 2 additions & 2 deletions core/shared/src/test/scala/cats/effect/internals/RingBufferTests.scala
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -43,12 +43,12 @@ class RingBufferTests extends AnyFunSuite with Matchers with TestUtils {
test("writing elements") {
val buffer = new RingBuffer[Integer](4)
for (i <- 0 to 3) buffer.push(i)
buffer.toList shouldBe List(0, 1, 2, 3)
buffer.toList shouldBe List(3, 2, 1, 0)
}

test("overwriting elements") {
val buffer = new RingBuffer[Integer](4)
for (i <- 0 to 100) buffer.push(i)
buffer.toList shouldBe List(97, 98, 99, 100)
buffer.toList shouldBe List(100, 99, 98, 97)
}
}
20 changes: 20 additions & 0 deletions runtime-tests/src/test/scala/cats/effect/TracingTests.scala
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -16,6 +16,7 @@

package cats.effect

import cats.implicits._
import cats.effect.tracing.IOTrace
import org.scalatest.funsuite.AsyncFunSuite
import org.scalatest.matchers.should.Matchers
Expand All @@ -41,4 +42,23 @@ class TracingTests extends AsyncFunSuite with Matchers {
r.captured shouldBe 4
}
}

test("contextual exceptions are not augmented more than once") {
val task = for {
_ <- IO.pure(1)
_ <- IO.pure(2)
_ <- IO.pure(3)
_ <- IO.shift(executionContext)
_ <- IO.pure(1)
_ <- IO.pure(2)
_ <- IO.pure(3)
e1 <- IO.raiseError(new Throwable("Encountered an error")).attempt
e2 <- IO.pure(e1).rethrow.attempt
} yield (e1, e2)

for (r <- task.unsafeToFuture()) yield {
val (e1, e2) = r
e1.swap.toOption.get.getStackTrace.length shouldBe e2.swap.toOption.get.getStackTrace.length
}
}
}
Loading