spoa-mirror
spoa-mirror copied to clipboard
Published
20 hours ago •
haproxytech
haproxytech
Mirror request not sent despite received by spoa
I've been trying to figure out why mirror requests are not sent. After a whole day of debugging I think (to best of my knowledge) the issue is in spoa-mirror. Some hints or guidance would be much appreciate to move forward on this.
My setup is using docker-compose with
- web server
- proxy
- haproxy 2.1.7
- spoa-mirror 1.2.6 (built with
--enable-debug)
From my logs I can see that requests are fwd to web server and request is received by engine but for some reason spoa-mirror is not sending. I'm using service like requestbin to log mirror request. The tests are done at super low scale.
Below is debug log
proxy | [ 1][ 11.497047] <1:28> --> Receiving data
proxy | [ 1][ 11.497083] <1:28> 4/4/4 byte(s) received frame length
proxy | [ 1][ 11.497089] <1:28> 129/129/129 byte(s) received frame data
proxy | [ 1][ 11.497092] <1:28> New frame of 129 bytes received: <0100000001000012737570706f727465642d76657273696f6e730803322e300e6d61782d6672616d652d73697a6503fcf0300c6361706162696c69746965730810706970656c696e696e672c6173796e6309656e67696e652d6964082435323236346437652d646330632d343564372d383735662d333330346366653833343661> <........supported-versions..2.0.max-frame-size...0.capabilities..pipelining,async.engine-id.$52264d7e-dc0c-45d7-875f-3304cfe8346a>
proxy | [ 1][ 11.497093] <1> --> HAPROXY-HELLO decoding frame
proxy | [ 1][ 11.497095] <1> --> HAPROXY-HELLO header 1 0x01000000 0 0
proxy | [ 1][ 11.497096] <1> --> HAPROXY-HELLO stream-id=0 - frame-id=0
proxy | [ 1][ 11.497098] <1> K/V item: key=supported-versions
proxy | [ 1][ 11.497100] <1> --> HAPROXY-HELLO supported versions: 2.0
proxy | [ 1][ 11.497101] <1> K/V item: key=max-frame-size
proxy | [ 1][ 11.497101] <1> --> HAPROXY-HELLO maximum frame size: 102396
proxy | [ 1][ 11.497102] <1> K/V item: key=capabilities
proxy | [ 1][ 11.497103] <1> --> HAPROXY-HELLO capabilities check: pipelining,async
proxy | [ 1][ 11.497104] <1> --> HAPROXY-HELLO capabilities set: pipelining async
proxy | [ 1][ 11.497104] <1> K/V item: key=engine-id
proxy | [ 1][ 11.497105] <1> --> HAPROXY-HELLO engine id: 52264d7e-dc0c-45d7-875f-3304cfe8346a
proxy | [ 1][ 11.497108] <1> <-- AGENT-HELLO encoding frame
proxy | [ 1][ 11.497111] <1> <-- AGENT-HELLO stream-id=0 - frame-id=0
proxy | [ 1][ 11.497112] <1> <-- AGENT-HELLO version: 2.0
proxy | [ 1][ 11.497113] <1> <-- AGENT-HELLO maximum frame size: 102396
proxy | [ 1][ 11.497113] <1> <-- AGENT-HELLO capabilities:
proxy | [ 1][ 11.497118] <1:28> <-- Sending data
proxy | [ 1][ 11.497150] <1:28> 4/4/4 byte(s) send frame length
proxy | [ 1][ 11.497162] <1:28> 54/54/54 byte(s) send frame data
proxy | [ 1][ 11.497164] <1:28> Frame of 54 bytes sent: <650000000100000776657273696f6e0803322e300e6d61782d6672616d652d73697a6503fcf0300c6361706162696c69746965730800> <e.......version..2.0.max-frame-size...0.capabilities..>
proxy | [ 1][ 11.497233] <1:28> --> Receiving data
proxy | [ 1][ 11.497238] <1:28> 4/4/4 byte(s) received frame length
proxy | [ 1][ 11.497240] <1:28> 369/369/369 byte(s) received frame data
proxy | [ 1][ 11.497245] <1:28> New frame of 369 bytes received: <030000000100010d6d6972726f726d657373616765050a6172675f6d6574686f640804504f5354086172675f70617468081f2f74686972642d70617274792f61707073666c7965722f3232323232323234076172675f7665720803312e31086172675f6864727309dc0c636f6e74656e742d74797065106170706c69636174696f6e2f6a736f6e0a757365722d6167656e7415506f73746d616e52756e74696d652f372e32352e3006616363657074032a2f2a0d63616368652d636f6e74726f6c086e6f2d63616368650d706f73746d616e2d746f6b656e2465613138613263382d326136322d343133612d623636632d65643462383830366139386304686f73740c6c6f63616c686f73743a37370f6163636570742d656e636f64696e6711677a69702c206465666c6174652c2062720e636f6e74656e742d6c656e6774680233330000086172675f626f647909217b0a2020226465766963655f63617465676f7279223a202270686f6e65220a7d0a> <........mirrormessage..arg_method..POST.arg_path../third-party/appsflyer/22222224.arg_ver..1.1.arg_hdrs...content-type.application/json.user-agent.PostmanRuntime/7.25.0.accept.*/*.cache-control.no-cache.postman-token$ea18a2c8-2a62-413a-b66c-ed4b8806a98c.host.localhost:77.accept-encoding.gzip, deflate, br.content-length.33...arg_body.!{. "device_category": "phone".}.>
proxy | [ 1][ 11.497246] <1> --> HAPROXY-NOTIFY decoding frame
proxy | [ 1][ 11.497247] <1> --> HAPROXY-NOTIFY header 3 0x01000000 0 1
proxy | [ 1][ 11.497248] <1> --> HAPROXY-NOTIFY stream-id=0 - frame-id=1
proxy | [ 1][ 11.497249] <1> --> HAPROXY-NOTIFY - unfragmented frame received - frag_len=0 - len=369 - offset=7
proxy | [ 1][ 11.497253] <1> Process frame messages: stream-id=0 - frame-id=1 - length=362 bytes
proxy | [ 1][ 11.497254] <1> Process SPOE Message 'mirrormessage'
proxy | [ 1][ 11.497255] <1> Skip message argument: name=arg_method
proxy | [ 1][ 11.497256] <1> Skip message argument: name=arg_path
proxy | [ 1][ 11.497256] <1> Skip message argumentSPOE: [mirroragent] <EVENT:on-frontend-http-request> sid=0 st=0 0/0/0/0/0 1/1 0/0 0/1
proxy | 172.21.0.1:34944 [16/Jun/2020:00:54:10.113] proxy energon/e1 1/0/0/590/591 200 100 - - ---- 1/1/0/0/0 0/0 "POST /third-party/appsflyer/22222224 HTTP/1.1"
energon | 2020-06-16 00:54:10,901 [kafka-producer-network-thread | producer-1] INFO com.activision.ds.energon.writers.KafkaWriter - Metrics sentdev.appsflyer.raw.json
proxy | SPOE: [mirroragent] <EVENT:on-frontend-http-request> sid=3 st=0 0/0/0/0/0 1/2 0/0 0/2
proxy | : name=arg_ver
proxy | [ 1][ 11.497289] <1> Skip message argument: name=arg_hdrs
proxy | [ 1][ 11.497291] <1> Skip message argument: name=arg_body
proxy | [ 1][ 11.497292] <1> <-- ACK encoding frame
proxy | [ 1][ 11.497293] <1> <-- ACK stream-id=0 - frame-id=1
proxy | [ 1][ 11.497298] <1:28> <-- Sending data
proxy | [ 1][ 11.497318] <1:28> 4/4/4 byte(s) send frame length
proxy | [ 1][ 11.497329] <1:28> 7/7/7 byte(s) send frame data
proxy | [ 1][ 11.497331] <1:28> Frame of 7 bytes sent: <67000000010001> <g......>
proxy | [ 1][ 15.052326] <1:28> --> Receiving data
proxy | [ 1][ 15.052338] <1:28> 4/4/4 byte(s) received frame length
proxy | [ 1][ 15.052341] <1:28> 369/369/369 byte(s) received frame data
proxy | [ 1][ 15.052346] <1:28> New frame of 369 bytes received: <030000000103010d6d6972726f726d657373616765050a6172675f6d6574686f640804504f5354086172675f70617468081f2f74686972642d70617274792f61707073666c7965722f3232323232323234076172675f7665720803312e31086172675f6864727309dc0c636f6e74656e742d74797065106170706c69636174696f6e2f6a736f6e0a757365722d6167656e7415506f73746d616e52756e74696d652f372e32352e3006616363657074032a2f2a0d63616368652d636f6e74726f6c086e6f2d63616368650d706f73746d616e2d746f6b656e2433383362666666642d373962632d346231382d623034322d34343232633566396638353004686f73740c6c6f63616c686f73743a37370f6163636570742d656e636f64696e6711677a69702c206465666c6174652c2062720e636f6e74656e742d6c656e6774680233330000086172675f626f647909217b0a2020226465766963655f63617465676f7279223a202270686f6e65220a7d0a> <........mirrormessage..arg_method..POST.arg_path../third-party/appsflyer/22222224.arg_ver..1.1.arg_hdrs...content-type.application/json.user-agent.PostmanRuntime/7.25.0.accept.*/*.cache-control.no-cache.postman-token$383bfffd-79bc-4b18-b042-4422c5f9f850.host.localhost:77.accept-encoding.gzip, deflate, br.content-length.33...arg_body.!{. "device_category": "phone".}.>
proxy | [ 1][ 15.052347] <1> --> HAPROXY-NOTIFY decoding frame
proxy | [ 1][ 15.052350] <1> --> HAPROXY-NOTIFY header 3 0x01000000 3 1
proxy | [ 1][ 15.052351] <1> --> HAPROXY-NOTIFY stream-id=3 - frame-id=1
proxy | [ 1][ 15.052352] <1> --> HAPROXY-NOTIFY - unfragmented frame received - frag_len=0 - len=369 - offset=7
proxy | [ 1][ 15.052356] <1> Process frame messages: stream-id=3 - frame-id=1 - length=362 bytes
proxy | [ 1][ 15.052357] <1> Process SPOE Message 'mirrormessage'
proxy | [ 1][ 15.052358] <1> Skip message argument: name=arg_method
proxy | [ 1][ 15.052359] <1> Skip message argument: name=arg_path
proxy | [ 1][ 15.052360] <1> Skip message argument: name=arg_ver
proxy | [ 1][ 15.052361] <1> Skip message argument: name=arg_hdrs
proxy | [ 1][ 15.052361] <1> Skip message argument: name=arg_body
proxy | [ 1][ 15.052362] <1> <-- ACK encoding frame
proxy | [ 1][ 15.052364] <1> <-- ACK stream-id=3 - frame-id=1
proxy | [ 1][ 15.052368] <1:28> <-- Sending data
proxy | [ 1][ 15.052381] <1:28> 4/4/4 byte(s) send frame length
proxy | [ 1][ 15.052388] <1:28> 7/7/7 byte(s) send frame data
proxy | [ 1][ 15.052390] <1:28> Frame of 7 bytes sent: <67000000010301> <g......>
proxy | [ 2][ 15.052479] <2:29> --> Receiving data
proxy | [ 2][ 15.052487] <2:29> 4/4/4 byte(s) received frame length
proxy | [ 2][ 15.052490] <2:29> 129/129/129 byte(s) received frame data
proxy | [ 2][ 15.052507] <2:29> New frame of 129 bytes received: <0100000001000012737570706f727465642d76657273696f6e730803322e300e6d61782d6672616d652d73697a6503fcf0300c6361706162696c69746965730810706970656c696e696e672c6173796e6309656e67696e652d6964082435323236346437652d646330632d343564372d383735662d333330346366653833343661> <........supported-versions..2.0.max-frame-size...0.capabilities..pipelining,async.engine-id.$52264d7e-dc0c-45d7-875f-3304cfe8346a>
proxy | [ 2][ 15.052510] <2> --> HAPROXY-HELLO decoding frame
proxy | [ 2][ 15.052511] <2> --> HAPROXY-HELLO header 1 0x01000000 0 0
proxy | [ 2][ 15.052513] <2> --> HAPROXY-HELLO stream-id=0 - frame-id=0
proxy | [ 2][ 15.052514] <2> K/V item: key=supported-versions
proxy | [ 2][ 15.052516] <2> --> HAPROXY-HELLO supported versions: 2.0
proxy | [ 2][ 15.052517] <2> K/V item: key=max-frame-size
proxy | [ 2][ 15.052518] <2> --> HAPROXY-HELLO maximum frame size: 102396
proxy | [ 2][ 15.052518] <2> K/V item: key=capabilities
proxy | [ 2][ 15.05172.21.0.1:34944 [16/Jun/2020:00:54:13.670] proxy energon/e1 1/0/0/4/5 200 100 - - ---- 1/1/0/0/0 0/0 "POST /third-party/appsflyer/22222224 HTTP/1.1"
I also observing broken pipe and haproxy-disconnect. Not sure if they are worth any concern. Happy to provide more info. Thank you for your help in advance.
Hello @rchien,
it seems to me that the problem is related to the entries 'Skip message argument' in the log. I'll take a closer look today and get back to you.
Best regards, Miroslav Zagorac
Hello,
alas, I forgot to answer @rchien's question.. I apologize. The problem is that the argument for "spoe-message" can only be one of the following: 'check-client-ip', 'test' and 'mirror'. He seems to have written 'mirrormessage' as an argument, so anything after that for that group is ignored. This also applies to the argument of the keyword 'messages' in the group 'spoe-agent'.
Hello,
alas, I forgot to answer @rchien's question.. I apologize. The problem is that the argument for "spoe-message" can only be one of the following: 'check-client-ip', 'test' and 'mirror'. He seems to have written 'mirrormessage' as an argument, so anything after that for that group is ignored. This also applies to the argument of the keyword 'messages' in the group 'spoe-agent'.
Thank you very much. It also solved my problem too.