{"action":"created","issue":{"url":"https://api.github.com/repos/micronaut-projects/micronaut-core/issues/504","repository_url":"https://api.github.com/repos/micronaut-projects/micronaut-core","labels_url":"https://api.github.com/repos/micronaut-projects/micronaut-core/issues/504/labels{/name}","comments_url":"https://api.github.com/repos/micronaut-projects/micronaut-core/issues/504/comments","events_url":"https://api.github.com/repos/micronaut-projects/micronaut-core/issues/504/events","html_url":"https://github.com/micronaut-projects/micronaut-core/issues/504","id":351724154,"node_id":"MDU6SXNzdWUzNTE3MjQxNTQ=","number":504,"title":"Duplicate Controller method invocation when using HttpServerFilter","user":{"login":"mmindenhall","id":1106269,"node_id":"MDQ6VXNlcjExMDYyNjk=","avatar_url":"https://avatars3.githubusercontent.com/u/1106269?v=4","gravatar_id":"","url":"https://api.github.com/users/mmindenhall","html_url":"https://github.com/mmindenhall","followers_url":"https://api.github.com/users/mmindenhall/followers","following_url":"https://api.github.com/users/mmindenhall/following{/other_user}","gists_url":"https://api.github.com/users/mmindenhall/gists{/gist_id}","starred_url":"https://api.github.com/users/mmindenhall/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/mmindenhall/subscriptions","organizations_url":"https://api.github.com/users/mmindenhall/orgs","repos_url":"https://api.github.com/users/mmindenhall/repos","events_url":"https://api.github.com/users/mmindenhall/events{/privacy}","received_events_url":"https://api.github.com/users/mmindenhall/received_events","type":"User","site_admin":false},"labels":[{"id":943282090,"node_id":"MDU6TGFiZWw5NDMyODIwOTA=","url":"https://api.github.com/repos/micronaut-projects/micronaut-core/labels/closed:%20notabug","name":"closed: notabug","color":"21b2a1","default":false},{"id":942494321,"node_id":"MDU6TGFiZWw5NDI0OTQzMjE=","url":"https://api.github.com/repos/micronaut-projects/micronaut-core/labels/status:%20awaiting%20feedback","name":"status: awaiting feedback","color":"f0ff6b","default":false},{"id":949471571,"node_id":"MDU6TGFiZWw5NDk0NzE1NzE=","url":"https://api.github.com/repos/micronaut-projects/micronaut-core/labels/status:%20awaiting%20validation","name":"status: awaiting validation","color":"5319e7","default":false}],"state":"closed","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":4,"created_at":"2018-08-17T20:13:10Z","updated_at":"2018-08-27T08:16:33Z","closed_at":"2018-08-27T08:16:33Z","author_association":"NONE","body":"This issue happens with java and kotlin (albeit with slightly different output).  I didn't try to reproduce with groovy, but assume the behavior would be similar.  When using an HttpServerFilter, we are seeing an endpoint in our controller invoked a second time.\r\n\r\n### Steps to Reproduce\r\n\r\n1. Clone [my fork of micronaut-examples](https://github.com/mmindenhall/micronaut-examples)\r\n1. Check out duplicate-invocation branch\r\n1. Run the hello-world-kotlin or hello-world-java project\r\n1. Hit the /hello/{name} endpoint\r\n1. Observe the output\r\n\r\n### Detailed Description\r\n\r\nThis is the output of the **first endpoint invocation** (kotlin):\r\n\r\n```\r\nnioEventLoopGroup-1-2 [HelloFilter] doFilter (1) before proceed\r\nnioEventLoopGroup-1-2 [HelloFilter] doFilter (2) after proceed\r\nnioEventLoopGroup-1-2 [HelloResponseFilterSubscriber] onSubscribe requested 1\r\nnioEventLoopGroup-1-2 [HelloController] hello endpoint invoked\r\nnioEventLoopGroup-1-2 [HelloResponseFilterSubscriber] onNext invoked with response: 200 Ok\r\nnioEventLoopGroup-1-2 [HelloResponseFilterSubscriber] onComplete\r\nnioEventLoopGroup-1-2 [HelloFilter] doFilter (3) after subscribe\r\n\r\npool-1-thread-1 [HelloController] hello endpoint invoked\r\n\r\nnioEventLoopGroup-1-2 [HelloFilter] doFilter (1) before proceed\r\nnioEventLoopGroup-1-2 [HelloFilter] doFilter (2) after proceed\r\nnioEventLoopGroup-1-2 [HelloResponseFilterSubscriber] onSubscribe requested 1\r\nnioEventLoopGroup-1-2 [HelloResponseFilterSubscriber] onNext invoked with response: 404 Not Found\r\nnioEventLoopGroup-1-2 [HelloResponseFilterSubscriber] onComplete\r\nnioEventLoopGroup-1-2 [HelloFilter] doFilter (3) after subscribe\r\n```\r\n\r\nI've added some newlines to make it easier to follow.  The first 7 lines of output are expected.  Then on the next line, the endpoint is invoked for a second time (but on a pool thread rather than nioEventLoopGroup thread).  Then, over the last 6 lines, the filter is also invoked a second time (with the publisher emitting a 404 response).\r\n\r\nThis is the output on **each subsequent endpoint invocation** (kotlin):\r\n\r\n```\r\nnioEventLoopGroup-1-3 [HelloFilter] doFilter (1) before proceed\r\nnioEventLoopGroup-1-3 [HelloFilter] doFilter (2) after proceed\r\nnioEventLoopGroup-1-3 [HelloResponseFilterSubscriber] onSubscribe requested 1\r\nnioEventLoopGroup-1-3 [HelloController] hello endpoint invoked\r\nnioEventLoopGroup-1-3 [HelloResponseFilterSubscriber] onNext invoked with response: 200 Ok\r\nnioEventLoopGroup-1-3 [HelloResponseFilterSubscriber] onComplete\r\nnioEventLoopGroup-1-3 [HelloFilter] doFilter (3) after subscribe\r\npool-1-thread-2 [HelloController] hello endpoint invoked\r\n```\r\n\r\nNow the filter/subscriber are invoked just once, but the endpoint method is invoked twice (once in event loop, once in pool thread).\r\n\r\nThe behavior is slightly different with Java.  All invocations (first and all subsequent) produce the following:\r\n\r\n```\r\nnioEventLoopGroup-1-2 [HelloFilter] doFilter(1) before proceed\r\nnioEventLoopGroup-1-2 [HelloFilter] doFilter(2) after proceed\r\nnioEventLoopGroup-1-2 [HelloResponseFilterSubscriber] onSubscribe requested 1\r\nnioEventLoopGroup-1-2 [HelloController] hello endpoint invoked\r\nnioEventLoopGroup-1-2 [HelloResponseFilterSubscriber] onNext invoked with response: 200 Ok\r\nnioEventLoopGroup-1-2 [HelloResponseFilterSubscriber] onComplete\r\nnioEventLoopGroup-1-2 [HelloFilter] doFilter(3) after subscribe\r\nnioEventLoopGroup-1-2 [HelloController] hello endpoint invoked\r\n```\r\n\r\nSo with Java, the endpoint is invoked twice, but always on the event loop thread (presumably due to the `Single<String>` return type). \r\n\r\n- **Operating System**: MacOS\r\n- **Micronaut Version:** 1.0.0.M4\r\n- **JDK Version:** 1.8.0_152\r\n"},"comment":{"url":"https://api.github.com/repos/micronaut-projects/micronaut-core/issues/comments/416151273","html_url":"https://github.com/micronaut-projects/micronaut-core/issues/504#issuecomment-416151273","issue_url":"https://api.github.com/repos/micronaut-projects/micronaut-core/issues/504","id":416151273,"node_id":"MDEyOklzc3VlQ29tbWVudDQxNjE1MTI3Mw==","user":{"login":"graemerocher","id":66626,"node_id":"MDQ6VXNlcjY2NjI2","avatar_url":"https://avatars2.githubusercontent.com/u/66626?v=4","gravatar_id":"","url":"https://api.github.com/users/graemerocher","html_url":"https://github.com/graemerocher","followers_url":"https://api.github.com/users/graemerocher/followers","following_url":"https://api.github.com/users/graemerocher/following{/other_user}","gists_url":"https://api.github.com/users/graemerocher/gists{/gist_id}","starred_url":"https://api.github.com/users/graemerocher/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/graemerocher/subscriptions","organizations_url":"https://api.github.com/users/graemerocher/orgs","repos_url":"https://api.github.com/users/graemerocher/repos","events_url":"https://api.github.com/users/graemerocher/events{/privacy}","received_events_url":"https://api.github.com/users/graemerocher/received_events","type":"User","site_admin":false},"created_at":"2018-08-27T08:16:33Z","updated_at":"2018-08-27T08:16:33Z","author_association":"MEMBER","body":"This is not a bug, you should not subscribe to the published returned from `proceed`. See https://github.com/micronaut-projects/micronaut-core/blob/master/tracing/src/main/java/io/micronaut/tracing/instrument/http/OpenTracingServerFilter.java for an example of decorating the returned publisher"}}
{"actor":{"display_login":"graemerocher"}}