Unable to forward write requests to master

Lazar_Bodor · September 20, 2017, 4:02am

Hi,

I’ve set up a 3-node cluster in AWS running version 4.0.2. Write requests sent to slaves over HTTP are not forwarded to the master node. The client gets HTTP 500, and the slaves log files contain the following exception trace:

System.FormatException: One of the identified items was in an invalid format.

at System.Net.Http.Headers.HttpHeaders.AddInternal (System.String name, System.Collections.Generic.IEnumerable`1[T] values, System.Net.Http.Headers.HeaderInfo headerInfo, System.Boolean ignoreInvalid) [0x0004c] in <41c316444c8a4380b9344ba09eeb18de>:0

at System.Net.Http.Headers.HttpHeaders.Add (System.String name, System.Collections.Generic.IEnumerable`1[T] values) [0x0001b] in <41c316444c8a4380b9344ba09eeb18de>:0

at System.Net.Http.Headers.HttpHeaders.Add (System.String name, System.String value) [0x00000] in <41c316444c8a4380b9344ba09eeb18de>:0

at EventStore.Core.Services.HttpSendService.ForwardRequest (EventStore.Transport.Http.EntityManagement.HttpEntityManager manager, System.Uri forwardUri) [0x00291] in <9e5f3ee780fe4efca17196a08aa2afeb>:0

at EventStore.Core.Services.HttpSendService.EventStore.Core.Services.Transport.Http.IHttpForwarder.ForwardRequest (EventStore.Transport.Http.EntityManagement.HttpEntityManager manager) [0x0006c] in <9e5f3ee780fe4efca17196a08aa2afeb>:0

at EventStore.Core.Services.Transport.Http.Controllers.UsersController.GetUser (EventStore.Transport.Http.EntityManagement.HttpEntityManager http, System.UriTemplateMatch match) [0x0000d] in <9e5f3ee780fe4efca17196a08aa2afeb>:0

at EventStore.Core.Services.Transport.Http.HttpService+c__AnonStorey0.<>m__0 (EventStore.Transport.Http.EntityManagement.HttpEntityManager man, System.UriTemplateMatch match) [0x00000] in <9e5f3ee780fe4efca17196a08aa2afeb>:0

at (wrapper delegate-invoke) System.Func`3[EventStore.Transport.Http.EntityManagement.HttpEntityManager,System.UriTemplateMatch,EventStore.Core.Services.Transport.Http.RequestParams]:invoke_TResult_T1_T2 (EventStore.Transport.Http.EntityManagement.HttpEntityManager,System.UriTemplateMatch)

at EventStore.Core.Services.Transport.Http.AuthenticatedHttpRequestProcessor.ProcessRequest (EventStore.Core.Services.Transport.Http.HttpService httpService, EventStore.Transport.Http.EntityManagement.HttpEntity httpEntity) [0x0015f] in <9e5f3ee780fe4efca17196a08aa2afeb>:0

Here is the “modified options” section of the log:

Sep 20 03:56:56 ip-172-31-16-169 eventstored[18218]: [18218,01,03:56:56.358] MODIFIED OPTIONS:

Sep 20 03:56:56 ip-172-31-16-169 eventstored[18218]: RUN PROJECTIONS: All (Config File)

Sep 20 03:56:56 ip-172-31-16-169 eventstored[18218]: EXT IP: 172.31.16.169 (Config File)

Sep 20 03:56:56 ip-172-31-16-169 eventstored[18218]: INT IP: 172.31.16.169 (Config File)

Sep 20 03:56:56 ip-172-31-16-169 eventstored[18218]: EXT IP ADVERTISE AS: 13.210.86.10 (Config File)

Sep 20 03:56:56 ip-172-31-16-169 eventstored[18218]: INT IP ADVERTISE AS: 13.210.86.10 (Config File)

Sep 20 03:56:56 ip-172-31-16-169 eventstored[18218]: EXT HTTP PORT: 80 (Config File)

Sep 20 03:56:56 ip-172-31-16-169 eventstored[18218]: INT HTTP PORT: 2112 (Config File)

Sep 20 03:56:56 ip-172-31-16-169 eventstored[18218]: EXT TCP PORT: 1113 (Config File)

Sep 20 03:56:56 ip-172-31-16-169 eventstored[18218]: INT TCP PORT: 1112 (Config File)

Sep 20 03:56:56 ip-172-31-16-169 eventstored[18218]: EXT HTTP PREFIXES: http://*:80/ (Config File)

Sep 20 03:56:56 ip-172-31-16-169 eventstored[18218]: INT HTTP PREFIXES: http://*:2112/ (Config File)

Sep 20 03:56:56 ip-172-31-16-169 eventstored[18218]: ADD INTERFACE PREFIXES: false (Config File)

Sep 20 03:56:56 ip-172-31-16-169 eventstored[18218]: DISCOVER VIA DNS: false (Config File)

Sep 20 03:56:56 ip-172-31-16-169 eventstored[18218]: CLUSTER GOSSIP PORT: 2112 (Config File)

Sep 20 03:56:56 ip-172-31-16-169 eventstored[18218]: GOSSIP SEED: [ 13.210.56.177:2112, 52.65.228.195:2112 ] (Config File)

Sep 20 03:56:56 ip-172-31-16-169 eventstored[18218]: GOSSIP TIMEOUT MS: 10000 (Config File)

Sep 20 03:56:56 ip-172-31-16-169 eventstored[18218]: GOSSIP INTERVAL MS: 20000 (Config File)

Sep 20 03:56:56 ip-172-31-16-169 eventstored[18218]: INT TCP HEARTBEAT TIMEOUT: 10000 (Config File)

Sep 20 03:56:56 ip-172-31-16-169 eventstored[18218]: INT TCP HEARTBEAT INTERVAL: 10000 (Config File)

Sep 20 03:56:56 ip-172-31-16-169 eventstored[18218]: EXT TCP HEARTBEAT TIMEOUT: 10000 (Config File)

Sep 20 03:56:56 ip-172-31-16-169 eventstored[18218]: EXT TCP HEARTBEAT INTERVAL: 20000 (Config File)

Sep 20 03:56:56 ip-172-31-16-169 eventstored[18218]: CLUSTER SIZE: 3 (Config File)

Write requests sent to master are successful. I would appreciate any help in diagnosing and resolving this problem.

Kind Regards,

Lazar

shaan · September 20, 2017, 6:33am

Hello,

Can you please send us the HTTP request (including the headers) you’re sending to the slave node?

Regards

Shaan

shaan · September 20, 2017, 8:00am

It looks like a bug in Mono - if you have multiple Accept Types in the Accept header:
https://bugzilla.xamarin.com/show_bug.cgi?id=27352

I’ve reproduced it with the following:

curl -v -H “Accept: application/json; charset=utf-8,text/plain; charset=utf-8;” http://127.0.0.1:2113/users/admin

Please try to set the “Accept” header as “/”, it should then work fine.

Lazar_Bodor · September 20, 2017, 9:23pm

Hi,

Yes, the problem does seem to be caused by a bug in mono. At work, HTTP proxies are adding a header, which mono fails to parse. From home (no proxy), I am able to post the request successfully to both master and slave nodes. From behind the corporate proxy, on the other hand, I can only post successfully to master.

The request is:

curl -v -d “{}” “http://52.65.228.195/streams/object-0”
-u user.a:xxx \

-H "Content-Type:application/json" \

-H "ES-EventType: SomeEvent" \

-H "ES-EventId: B322E299-CB73-4B47-97C5-5054F920746F"

Output of curl verbose is:

Trying 143.174.101.29…
TCP_NODELAY set
Connected to proxy.inno.lan (143.174.101.29) port 3128 (#0)
Server auth using Basic with user ‘user.a’

POST http://52.65.228.195/streams/object-0 HTTP/1.1

Host: 52.65.228.195

Authorization: Basic dXNlci5hOmd1bWJ5MTIz

User-Agent: curl/7.55.1

Accept: /

Proxy-Connection: Keep-Alive

Content-Type:application/json

ES-EventType: SomeEvent

ES-EventId: B322E299-CB73-4B47-97C5-5054F920746F

Content-Length: 2

upload completely sent off: 2 out of 2 bytes
HTTP 1.0, assume close after body

< HTTP/1.0 500 Internal Server Error

< Access-Control-Allow-Methods:

< Access-Control-Allow-Headers: Content-Type, X-Requested-With, X-Forwarded-Host, X-Forwarded-Prefix, X-PINGOTHER, Authorization, ES-LongPoll, ES-ExpectedVersion, ES-EventId, ES-EventType, ES-RequiresMaster, ES-HardDelete, ES-ResolveLinkTos

< Access-Control-Allow-Origin: *

< Access-Control-Expose-Headers: Location, ES-Position, ES-CurrentVersion

< Content-Type:

< Server: Mono-HTTPAPI/1.0

< Date: Wed, 20 Sep 2017 20:45:01 GMT

< Content-Length: 0

< Age: 0

< X-Cache: MISS from proxy-innovation

< X-Cache-Lookup: MISS from proxy-innovation:3128

< Via: 1.1 sig4gaproxy05.sig.mgt.intellicentre.net.au, 1.0 proxy-innovation (squid/3.1.10)

HTTP/1.0 connection set to keep alive!

< Connection: keep-alive

<

Connection #0 to host proxy.inno.lan left intact

I’ve recompiled mono 4.6.2.16 (mcs/class/System.Net.Http/System.Net.Http.Headers/HttpHeaders.cs) to report the name and value of the header that it fails to parse. The exception now reads:

System.FormatException: name: Via, value: 1.1 proxy-innovation (squid/3.1.10), 1.1 sig4gaproxy78.sig.mgt.intellicentre.net.au 0A40447D

at System.Net.Http.Headers.HttpHeaders.AddInternal (System.String name, System.Collections.Generic.IEnumerable`1[T] values, System.Net.Http.Headers.HeaderInfo headerInfo, System.Boolean ignoreInvalid) [0x0004c] in /home/ubuntu/dev/mono/mcs/class/System.Net.Http/System.Net.Http.Headers/HttpHeaders.cs:196

at System.Net.Http.Headers.HttpHeaders.Add (System.String name, System.Collections.Generic.IEnumerable`1[T] values) [0x00011] in /home/ubuntu/dev/mono/mcs/class/System.Net.Http/System.Net.Http.Headers/HttpHeaders.cs:171

at System.Net.Http.Headers.HttpHeaders.Add (System.String name, System.String value) [0x00000] in /home/ubuntu/dev/mono/mcs/class/System.Net.Http/System.Net.Http.Headers/HttpHe…

It breaks on the multi-valued header “Via”.

By the way, this problem also affects the web UI on slaves: credentials are validated, but the UI remains stuck on the login page. The log shows the same exception.

Thank you very much for your help.

Kind Regards,

Lazar

shaan · September 21, 2017, 7:00am

Hi again,

Thanks for all the details.

I’ve tried with the Via header you provided.

In this case it’s not a bug with Mono, but it’s because of a malformed via header:

1.1 sig4gaproxy78.sig.mgt.intellicentre.net.au 0A40447D

0A40447D should be between brackets: (0A40447D) as per RFC 2616: https://tools.ietf.org/html/rfc2616#section-14.45

Regards

Shaan

shaan · September 21, 2017, 8:52am

Update:

Just for the records, the bug stated above https://bugzilla.xamarin.com/show_bug.cgi?id=27352 does not affect mono 4.6.2.16
Multiple “Accept” headers are accepted by a slave node and the request is forwarded.

The reason for the Invalid format exception in this query:

curl -v -H “Accept: application/json; charset=utf-8,text/plain; charset=utf-8;” http://127.0.0.1:2113/users/admin

is because of the semicolon at the end (not correct format)

Regards

Shaan

shaan · September 21, 2017, 9:21am

Thanks once again for reporting this Lazar.
Just submitted a fix by being a bit more lenient with the header formatting.

It should be present in the next release of EventStore.

Lazar_Bodor · September 22, 2017, 5:11am

That sounds great, Shaan. Thank you for your help.

Regards,

Lazar

Lazar_Bodor · October 12, 2017, 11:54pm

I have just upgraded to version 4.0.3 and can confirm that the new lenient parsing of HTTP headers has fixed my problem. Thanks again.

Lazar