Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Mirror request not sent despite received by spoa #13

Open
rchien opened this issue Jun 16, 2020 · 4 comments
Open

Mirror request not sent despite received by spoa #13

rchien opened this issue Jun 16, 2020 · 4 comments

Comments

@rchien
Copy link

rchien commented Jun 16, 2020

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.

@zaga00
Copy link
Member

zaga00 commented Aug 18, 2020

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

@T-bond
Copy link

T-bond commented Jul 10, 2023

Hello @rchien, @zaga00,

have you found any solution?

Best regards,
T-bond

@zaga00
Copy link
Member

zaga00 commented Jul 10, 2023

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'.

@T-bond
Copy link

T-bond commented Jul 10, 2023

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants