# \[APM-agent-go\] Some Error occurred while calling apmsql/conn.go's finishSpan method

**URL:** <https://discuss.elastic.co/t/apm-agent-go-some-error-occurred-while-calling-apmsql-conn-gos-finishspan-method/159333>\
**Category:** APM\
**Created:** [December 4, 2018, 10:12am UTC](https://discuss.elastic.co/t/apm-agent-go-some-error-occurred-while-calling-apmsql-conn-gos-finishspan-method/159333 "2018-12-04T10:12:56Z")\
**Posts on this page:** 13\
**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:** [December 4, 2018, 10:12am UTC](https://discuss.elastic.co/t/apm-agent-go-some-error-occurred-while-calling-apmsql-conn-gos-finishspan-method/159333/1 "2018-12-04T10:12:57Z")

</div>

I am using the 1.0 release of apm-agent-go on our project at test environments. And there are some errors of same type occur sometime as following:

```
{
  "library_frame": true,
  "exclude_from_grouping": false,
  "filename": "gocontext.go",
  "abs_path": "/buildpath/src/code.com/demo/vendor/github.com/elastic/apm-agent-go/gocontext.go",
  "line": {
    "number": 64
  },
  "module": "code.com/demo/vendor/github.com/elastic/apm-agent-go",
  "function": "CaptureError"
},
{
  "library_frame": true,
  "exclude_from_grouping": false,
  "filename": "conn.go",
  "abs_path": "/buildpath/src/code.com/demo/vendor/github.com/elastic/apm-agent-go/module/apmsql/conn.go",
  "line": {
    "number": 71
  },
  "module": "code.com/demo/vendor/github.com/elastic/apm-agent-go/module/apmsql",
  "function": "(*conn).finishSpan"
},
{
  "library_frame": true,
  "exclude_from_grouping": false,
  "filename": "conn.go",
  "abs_path": "/buildpath/src/code.com/demo/vendor/github.com/elastic/apm-agent-go/module/apmsql/conn.go",
  "line": {
    "number": 93
  },
  "module": "code.com/demo/vendor/github.com/elastic/apm-agent-go/module/apmsql",
  "function": "(*conn).QueryContext"
},
{
  "library_frame": true,
  "exclude_from_grouping": false,
  "abs_path": "/usr/local/go/src/database/sql/ctxutil.go",
  "filename": "ctxutil.go",
  "line": {
    "number": 48
  },
  "module": "database/sql",
  "function": "ctxDriverQuery"
},
{
  "library_frame": true,
  "exclude_from_grouping": false,
  "filename": "sql.go",
  "abs_path": "/usr/local/go/src/database/sql/sql.go",
  "line": {
    "number": 1320
  },
  "module": "database/sql",
  "function": "(*DB).queryDC.func1"
},
{
  "library_frame": true,
  "exclude_from_grouping": false,
  "filename": "sql.go",
  "abs_path": "/usr/local/go/src/database/sql/sql.go",
  "line": {
    "number": 2867
  },
  "function": "withLock",
  "module": "database/sql"
},
{
  "library_frame": true,
  "exclude_from_grouping": false,
  "filename": "sql.go",
  "abs_path": "/usr/local/go/src/database/sql/sql.go",
  "line": {
    "number": 1319
  },
  "module": "database/sql",
  "function": "(*DB).queryDC"
},
{
  "library_frame": true,
  "exclude_from_grouping": false,
  "filename": "sql.go",
  "abs_path": "/usr/local/go/src/database/sql/sql.go",
  "line": {
    "number": 1304
  },
  "function": "(*DB).query",
  "module": "database/sql"
},
{
  "library_frame": true,
  "exclude_from_grouping": false,
  "abs_path": "/usr/local/go/src/database/sql/sql.go",
  "filename": "sql.go",
  "line": {
    "number": 1281
  },
  "module": "database/sql",
  "function": "(*DB).QueryContext"
},
{
  "exclude_from_grouping": false,
  "library_frame": true,
  "filename": "dbr.go",
  "abs_path": "/buildpath/src/code.com/demo/vendor/git.xiaojukeji.com/houxinzhu/dbr/dbr.go",
  "line": {
    "number": 161
  },
  "module": "code.com/demo/vendor/git.xiaojukeji.com/houxinzhu/dbr",
  "function": "query"
},
{
  "library_frame": true,
  "exclude_from_grouping": false,
  "filename": "select_builder.go",
  "abs_path": "/buildpath/src/code.com/demo/vendor/git.xiaojukeji.com/houxinzhu/dbr/select_builder.go",
  "line": {
    "number": 94
  },
  "module": "code.com/demo/vendor/git.xiaojukeji.com/houxinzhu/dbr",
  "function": "(*SelectBuilder).LoadContext"
},
{
  "exclude_from_grouping": false,
  "filename": "resource.go",
  "abs_path": "/buildpath/src/code.com/demo/server/model/resource.go",
  "line": {
    "number": 423
  },
  "module": "code.com/demo/server/model",
  "function": "(*Resource).GetTrashByDeadline"
},
{
  "exclude_from_grouping": false,
  "filename": "deletetrash.go",
  "abs_path": "/buildpath/src/code.com/demo/server/services/plugins/deletetrash.go",
  "line": {
    "number": 40
  },
  "function": "(*TrashConfig).cronDeleteTrash",
  "module": "code.com/demo/server/services/plugins"
},
{
  "exclude_from_grouping": false,
  "filename": "deletetrash.go",
  "abs_path": "/buildpath/src/code.com/demo/server/services/plugins/deletetrash.go",
  "line": {
    "number": 28
  },
  "module": "code.com/demo/server/services/plugins",
  "function": "(*TrashConfig).CronDeleteTrash"
},
{
  "exclude_from_grouping": false,
  "abs_path": "/buildpath/src/code.com/demo/server/services/plugins/deletetrash.go",
  "filename": "deletetrash.go",
  "line": {
    "number": 81
  },
  "module": "code.com/demo/server/services/plugins",
  "function": "(*TrashConfig).CronDeleteTrash-fm"
},
{
  "exclude_from_grouping": false,
  "filename": "cron.go",
  "abs_path": "/buildpath/src/code.com/demo/server/common/cron/cron.go",
  "line": {
    "number": 33
  },
  "function": "Cron.CronJob.func1",
  "module": "code.com/demo/server/common/cron"
},
{
  "exclude_from_grouping": false,
  "library_frame": true,
  "filename": "cron.go",
  "abs_path": "/buildpath/src/code.com/demo/vendor/github.com/robfig/cron/cron.go",
  "line": {
    "number": 83
  },
  "module": "code.com/demo/vendor/github.com/robfig/cron",
  "function": "FuncJob.Run"
},
{
  "library_frame": true,
  "exclude_from_grouping": false,
  "filename": "asm_amd64.s",
  "abs_path": "/usr/local/go/src/runtime/asm_amd64.s",
  "line": {
    "number": 2337
  },
  "function": "goexit",
  "module": "runtime"
}    

```

Any clue of what would be the problem? Thanks.

---

<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:** [December 4, 2018, 11:52am UTC](https://discuss.elastic.co/t/apm-agent-go-some-error-occurred-while-calling-apmsql-conn-gos-finishspan-method/159333/2 "2018-12-04T11:52:28Z")

</div>

`module/apmsql` reports the errors reutrned by the SQL query. On the errors page there should be an "Exception message" at the top. What does it say?

Perhaps the apmsql code is a bit too eager, and is reporting errors it should not.

---

<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:** [December 4, 2018, 1:41pm UTC](https://discuss.elastic.co/t/apm-agent-go-some-error-occurred-while-calling-apmsql-conn-gos-finishspan-method/159333/3 "2018-12-04T13:41:44Z")

</div>

Highlighted as "Bad Connection."

---

<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:** [December 5, 2018, 1:21am UTC](https://discuss.elastic.co/t/apm-agent-go-some-error-occurred-while-calling-apmsql-conn-gos-finishspan-method/159333/4 "2018-12-05T01:21:16Z")

</div>

> [@Barry\_Zhong](#):
>
> Highlighted as "Bad Connection."

Thanks, I think I see the issue.

There is a special error (database/sql/driver.ErrBaddConn) that `database/sql` drivers can return to indicate that a connection is bad, and a new connection should be made. I'll change apmsql to not report these errors. We should also not report database/sql.ErrNoRows; I'll update the code to ignore that while I'm there.

---

<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:** [December 5, 2018, 1:35am UTC](https://discuss.elastic.co/t/apm-agent-go-some-error-occurred-while-calling-apmsql-conn-gos-finishspan-method/159333/5 "2018-12-05T01:35:52Z")

</div>

@Barry_Zhong I have filed [https://github.com/elastic/apm-agent-go/issues/345](https://github.com/elastic/apm-agent-go/issues/345), which you can subscribe to for updates. Thanks for reporting the issue!

---

<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:** [December 5, 2018, 3:28am UTC](https://discuss.elastic.co/t/apm-agent-go-some-error-occurred-while-calling-apmsql-conn-gos-finishspan-method/159333/6 "2018-12-05T03:28:17Z")

</div>

Sometime Highlighted as "context canceled"

---

<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:** [December 5, 2018, 3:47am UTC](https://discuss.elastic.co/t/apm-agent-go-some-error-occurred-while-calling-apmsql-conn-gos-finishspan-method/159333/7 "2018-12-05T03:47:58Z")

</div>

> [@Barry\_Zhong](#):
>
> Sometime Highlighted as "context canceled"

Thanks. I've opened [module/apmsql: don't report "context canceled" errors · Issue #347 · elastic/apm-agent-go · GitHub](https://github.com/elastic/apm-agent-go/issues/347) for that.

---

<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:** [December 5, 2018, 9:39am UTC](https://discuss.elastic.co/t/apm-agent-go-some-error-occurred-while-calling-apmsql-conn-gos-finishspan-method/159333/8 "2018-12-05T09:39:21Z")

</div>

Hey @axw the "context canceled" one may not be an issue, we are using a wrong context instance, which will be canceled due to http request process complete, inside a forked goroutine. Sorry for that, and the error information is still valuable, since it indicates there is a functional bug. Such as the sql statement running with a canceled context will return unexpected result.

---

<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:** [December 5, 2018, 9:57am UTC](https://discuss.elastic.co/t/apm-agent-go-some-error-occurred-while-calling-apmsql-conn-gos-finishspan-method/159333/9 "2018-12-05T09:57:36Z")

</div>

> [@Barry\_Zhong](#):
>
> Hey @axw the "context canceled" one may not be an issue, we are using a wrong context instance, which will be canceled due to http request process complete, inside a forked goroutine. Sorry for that, and the error information is still valuable, since it indicates there is a functional bug. Such as the sql statement running with a canceled context will return unexpected result.

For "context canceled", the APM agent can't tell an expected error from an unexpected one. I think expected "context canceled" errors would be the norm, which is why I went ahead and made the change.

In this case would you see an error further up the stack in the business logic?

---

<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:** [December 10, 2018, 2:03am UTC](https://discuss.elastic.co/t/apm-agent-go-some-error-occurred-while-calling-apmsql-conn-gos-finishspan-method/159333/10 "2018-12-10T02:03:37Z")

</div>

@Barry_Zhong not sure if you saw my reply, just pinging in case you did not.

I'd also restate what I said, in case I was not clear. I think in most cases that cancelling context would be intentional, rather than a coding error. Because of that, I think it makes sense to ignore such errors, which are used for control flow rather than to indicate a problem.

In your business logic, i.e. in your `cronDeleteTrash` code, I think you probably don't expect context to be cancelled - right? So can you instead report logic errors up to APM in that code?

---

<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:** [December 10, 2018, 6:21am UTC](https://discuss.elastic.co/t/apm-agent-go-some-error-occurred-while-calling-apmsql-conn-gos-finishspan-method/159333/11 "2018-12-10T06:21:41Z")

</div>

@axw Andrew, thanks for keeping tight communications with us.

Conclusion: I do not think it is apm-agent-go's issue. It is our developer mis-use a context, which created from another http handler goroutine, which will be canceled very soon.

Indication: it seems that not every golang programmer uses Context in a right manner. I am not even a golang programmer 😜

One thing bothered me a lot is, when I want to apply apm-go-agent into our golang application, I had to face those unknown rabbit holes, and people felt nervous to lift apm as a production 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:** [December 10, 2018, 7:43am UTC](https://discuss.elastic.co/t/apm-agent-go-some-error-occurred-while-calling-apmsql-conn-gos-finishspan-method/159333/12 "2018-12-10T07:43:37Z")

</div>

@Barry_Zhong thanks for your reply.

> Conclusion: I do not think it is apm-agent-go's issue. It is our developer mis-use a context, which created from another http handler goroutine, which will be canceled very soon.
> 
> Indication: it seems that not every golang programmer uses Context in a right manner. I am not even a golang programmer 😜

OK. I think what might help is if we publish some more in-depth examples covering a variety of coding patterns, such as goroutine pools like you have in your application. The focus of these examples would be (a) when/how to report transactions, spans, and errors, and (b) how to propagate context.

I have opened [Publish more in-depth examples for instrumentation and context propagation · Issue #385 · elastic/apm-agent-go · GitHub](https://github.com/elastic/apm-agent-go/issues/385) to track this.

> One thing bothered me a lot is, when I want to apply apm-go-agent into our golang application, I had to face those unknown rabbit holes, and people felt nervous to lift apm as a production solution :(.

Understood, and I'm sorry it hasn't gone smoother. I hope the value you're seeing outweighs the difficulties you've encountered so far.

Don't hesitate to reach out again if you run into any other issues. This is how we can make it better! 🙂

---

<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 31, 2018, 3:43am UTC](https://discuss.elastic.co/t/apm-agent-go-some-error-occurred-while-calling-apmsql-conn-gos-finishspan-method/159333/13 "2018-12-31T03:43:49Z")

</div>

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