# Apm-agent-go v0.5.2 panic with mu.Unlock

**URL:** <https://discuss.elastic.co/t/apm-agent-go-v0-5-2-panic-with-mu-unlock/156614>\
**Category:** APM\
**Created:** [November 14, 2018, 9:33am UTC](https://discuss.elastic.co/t/apm-agent-go-v0-5-2-panic-with-mu-unlock/156614 "2018-11-14T09:33:07Z")\
**Posts on this page:** 12\
**Page:** 1

<div class="post-metadata">

**Author:** ![Barry\_Zhong](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/barry_zhong/32/46786_2.png) [@Barry\_Zhong](https://discuss.elastic.co/u/Barry_Zhong)\
**Post date:** [November 14, 2018, 9:33am UTC](https://discuss.elastic.co/t/apm-agent-go-v0-5-2-panic-with-mu-unlock/156614/1 "2018-11-14T09:33:08Z")

</div>

I am using apm-agent-go inside my project, currently I got a crash when loading my application. I am not sure if it is the application's issue or apm-agent-go's issue. Any clue?

```auto
fatal error: sync: unlock of unlocked mutex

goroutine 77 [running]:
runtime.throw(0xe6b88d, 0x1e)
	/usr/local/go/src/runtime/panic.go:616 +0x81 fp=0xc4295b8e40 sp=0xc4295b8e20 pc=0x42c801
sync.throw(0xe6b88d, 0x1e)
	/usr/local/go/src/runtime/panic.go:605 +0x35 fp=0xc4295b8e60 sp=0xc4295b8e40 pc=0x42c775
sync.(*Mutex).Unlock(0xc424f11858)
	/usr/local/go/src/sync/mutex.go:184 +0xc2 fp=0xc4295b8e88 sp=0xc4295b8e60 pc=0x470ce2
code.xiaojukeji.com/cloud-disk-server/vendor/github.com/elastic/apm-agent-go.(*Transaction).StartSpan(0xc424f11600, 0xc421db8e40, 0x14, 0xc420294ac0, 0xe, 0x0, 0xc421db8e40)
	/go/src/code.xiaojukeji.com/cloud-disk-server/vendor/github.com/elastic/apm-agent-go/span.go:44 +0x165 fp=0xc4295b8ef0 sp=0xc4295b8e88 pc=0x9bad25
code.xiaojukeji.com/cloud-disk-server/vendor/github.com/elastic/apm-agent-go.StartSpan(0xf20460, 0xc428c51bf0, 0xc421db8e40, 0x14, 0xc420294ac0, 0xe, 0xd1ec20, 0xc4240406ce, 0x7fb023550db0)
	/go/src/code.xiaojukeji.com/cloud-disk-server/vendor/github.com/elastic/apm-agent-go/gocontext.go:41 +0xa1 fp=0xc4295b8f50 sp=0xc4295b8ef0 pc=0x9b79f1
code.xiaojukeji.com/cloud-disk-server/vendor/github.com/elastic/apm-agent-go/module/apmsql.(*conn).startSpan(0xc4237909c0, 0xf20460, 0xc428c51bf0, 0xc421db8e40, 0x14, 0xc420294ac0, 0xe, 0xc4240406c0, 0x26, 0x0, ...)
	/go/src/code.xiaojukeji.com/cloud-disk-server/vendor/github.com/elastic/apm-agent-go/module/apmsql/conn.go:49 +0x81 fp=0xc4295b9040 sp=0xc4295b8f50 pc=0x9d96e1
code.xiaojukeji.com/cloud-disk-server/vendor/github.com/elastic/apm-agent-go/module/apmsql.(*conn).startStmtSpan(0xc4237909c0, 0xf20460, 0xc428c51bf0, 0xc4240406c0, 0x26, 0xc420294ac0, 0xe, 0xcf1520, 0x3000000000000000, 0xc4295b9328)
	/go/src/code.xiaojukeji.com/cloud-disk-server/vendor/github.com/elastic/apm-agent-go/module/apmsql/conn.go:45 +0xa6 fp=0xc4295b90b0 sp=0xc4295b9040 pc=0x9d9616
code.xiaojukeji.com/cloud-disk-server/vendor/github.com/elastic/apm-agent-go/module/apmsql.(*conn).QueryContext(0xc4237909c0, 0xf20460, 0xc428c51bf0, 0xc4240406c0, 0x26, 0x14a6430, 0x0, 0x0, 0x0, 0x0, ...)
	/go/src/cod

```

---

<div class="post-metadata">

**Author:** ![axw](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/axw/32/28197_2.png) [@axw](https://discuss.elastic.co/u/axw)\
**Post date:** [November 14, 2018, 10:10am UTC](https://discuss.elastic.co/t/apm-agent-go-v0-5-2-panic-with-mu-unlock/156614/2 "2018-11-14T10:10:46Z")

</div>

Hi Barry,

This could happen if you start a span referring to a transaction that has already been ended, like this:

```auto
tx := elasticapm.DefaultTracer.StartTransaction("name", "type")
ctx := elasticapm.ContextWithTransaction(context.Background(), tx)
...
tx.End()
...
elasticapm.StartSpan(ctx, "name", "type") // <- invalid after tx.End()

```

I see that the span is being created by module/apmsql. Is the query being run within a web request handler?

---

<div class="post-metadata">

**Author:** ![Barry\_Zhong](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/barry_zhong/32/46786_2.png) [@Barry\_Zhong](https://discuss.elastic.co/u/Barry_Zhong)\
**Post date:** [November 14, 2018, 10:11am UTC](https://discuss.elastic.co/t/apm-agent-go-v0-5-2-panic-with-mu-unlock/156614/3 "2018-11-14T10:11:40Z")

</div>

Yes, inside gin.

---

<div class="post-metadata">

**Author:** ![axw](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/axw/32/28197_2.png) [@axw](https://discuss.elastic.co/u/axw)\
**Post date:** [November 14, 2018, 10:18am UTC](https://discuss.elastic.co/t/apm-agent-go-v0-5-2-panic-with-mu-unlock/156614/4 "2018-11-14T10:18:48Z")

</div>

OK, one possibility is that your request handler is starting another goroutine which runs database queries, and you're passing the request context to that. The database queries are being run _after_ the request completes, which will cause the tracing to attempt to start a span after the transaction has finished.

Does that sound plausible?

---

<div class="post-metadata">

**Author:** ![Barry\_Zhong](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/barry_zhong/32/46786_2.png) [@Barry\_Zhong](https://discuss.elastic.co/u/Barry_Zhong)\
**Post date:** [November 14, 2018, 10:18am UTC](https://discuss.elastic.co/t/apm-agent-go-v0-5-2-panic-with-mu-unlock/156614/5 "2018-11-14T10:18:49Z")

</div>

It seems that we are using an asynchronous case(work pool), the error show up in work pool thread, it matches what you described. let me dive in. Thx

---

<div class="post-metadata">

**Author:** ![Barry\_Zhong](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/barry_zhong/32/46786_2.png) [@Barry\_Zhong](https://discuss.elastic.co/u/Barry_Zhong)\
**Post date:** [November 14, 2018, 10:43am UTC](https://discuss.elastic.co/t/apm-agent-go-v0-5-2-panic-with-mu-unlock/156614/6 "2018-11-14T10:43:20Z")

</div>

the basic process is like: req -\> pool -\> response, but the context is timed out while pooling, it seems like the context is timed out, but the transaction is still calling startSpan. There supposed to be design issues, but what's your suggestion for quick solution?

---

<div class="post-metadata">

**Author:** ![axw](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/axw/32/28197_2.png) [@axw](https://discuss.elastic.co/u/axw)\
**Post date:** [November 14, 2018, 11:13am UTC](https://discuss.elastic.co/t/apm-agent-go-v0-5-2-panic-with-mu-unlock/156614/7 "2018-11-14T11:13:30Z")

</div>

> [@Barry\_Zhong](#):
>
> the basic process is like: req -\> pool -\> response, but the context is timed out while pooling, it seems like the context is timed out, but the transaction is still calling startSpan. There supposed to be design issues, but what's your suggestion for quick solution?

I see, thank you. I have created [Investigate safeguards for apm.StartSpan when ctx containing ended transaction/span · Issue #317 · elastic/apm-agent-go · GitHub](https://github.com/elastic/apm-agent-go/issues/317) to track this issue.

As a quick fix, you could create an intermediate span at a point where you know the request hasn't finished/timed out, and add that span to the context, but don't call its End method until you know no more queries will be sent.

So the order of events would be like:

```auto
tx := elasticapm.DefaultTracer.StartTransaction("name", "type")
ctx := elasticapm.ContextWithTransaction(context.Background(), tx)
...
intermediateSpan, ctx2 := elasticapm.StartSpan(ctx, "intermediate", "span")
...
tx.End()
...
elasticapm.StartSpan(ctx2, "name", "type").End()
...
intermediateSpan.End()

```

This should work because the transaction is not referenced after the call to StartSpan returns.

---

<div class="post-metadata">

**Author:** ![Barry\_Zhong](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/barry_zhong/32/46786_2.png) [@Barry\_Zhong](https://discuss.elastic.co/u/Barry_Zhong)\
**Post date:** [November 14, 2018, 12:09pm UTC](https://discuss.elastic.co/t/apm-agent-go-v0-5-2-panic-with-mu-unlock/156614/8 "2018-11-14T12:09:47Z")

</div>

Thx Andrew. Similarly, I am using following code at the beginning of WorkPool tasks, and it works as well.😋

```auto
tx := elasticapm.DefaultTracer.StartTransaction(name, "WorkPool")
defer tx.End()
context := elasticapm.ContextWithTransaction(context.Background(), tx)

```

So that those dbr/sql/http instrumenting works as expected. Eventually, those tx and spans showed up at Dashboard as a dedicated 'Type' -\> WorkPool in the middle of Request and Errors tabs.

---

<div class="post-metadata">

**Author:** ![axw](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/axw/32/28197_2.png) [@axw](https://discuss.elastic.co/u/axw)\
**Post date:** [November 14, 2018, 12:15pm UTC](https://discuss.elastic.co/t/apm-agent-go-v0-5-2-panic-with-mu-unlock/156614/9 "2018-11-14T12:15:06Z")

</div>

Great! You won't be able to see the SQL spans within the HTTP request transaction, but this seems like a good quick fix. Keep an eye on the issue I linked, I hope to have a solution in the agent in the near future.

---

<div class="post-metadata">

**Author:** ![axw](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/axw/32/28197_2.png) [@axw](https://discuss.elastic.co/u/axw)\
**Post date:** [November 19, 2018, 6:38am UTC](https://discuss.elastic.co/t/apm-agent-go-v0-5-2-panic-with-mu-unlock/156614/10 "2018-11-19T06:38:17Z")

</div>

@Barry_Zhong FYI I've just merged [https://github.com/elastic/apm-agent-go/pull/319](https://github.com/elastic/apm-agent-go/pull/319) which will go into the next release. This change will eliminate panics in situations like you described by treating call to StartSpan with an ended transaction as a no-op.

---

<div class="post-metadata">

**Author:** ![Barry\_Zhong](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/barry_zhong/32/46786_2.png) [@Barry\_Zhong](https://discuss.elastic.co/u/Barry_Zhong)\
**Post date:** [November 19, 2018, 9:45am UTC](https://discuss.elastic.co/t/apm-agent-go-v0-5-2-panic-with-mu-unlock/156614/12 "2018-11-19T09:45:36Z")

</div>

@axw Awesome!

---

<div class="post-metadata">

**Author:** ![system](https://us1.discourse-cdn.com/elastic/original/3X/1/a/1ac57faf039f6b580b3f104ef42a2a89e41014de.png) [@system](https://discuss.elastic.co/u/system)\
**Post date:** [December 10, 2018, 5:45am UTC](https://discuss.elastic.co/t/apm-agent-go-v0-5-2-panic-with-mu-unlock/156614/13 "2018-12-10T05:45:46Z")

</div>

This topic was automatically closed 20 days after the last reply. New replies are no longer allowed.