Skip to content

frequent test failure in t/90h2olog-selective-tracing.t #3057

Description

@kazuho

I added diag and what I see is below (note: this was the only one not ok being observed).

2022-07-19T03:40:57.8422278Z  35.723629         ok 1 - req: HTTP/1.1
2022-07-19T03:40:57.8422620Z  36.724764         ok 2 - h1-accept header in logs
2022-07-19T03:40:57.8422979Z  36.725051         not ok 3 - h1-close header in logs
2022-07-19T03:40:57.8423343Z  36.725329         #   Failed test 'h1-close header in logs'
2022-07-19T03:40:57.8423756Z  36.725333         #   at t/90h2olog-selective-tracing.t line 218.
2022-07-19T03:40:57.8424103Z  36.725447         #          got: '2'
2022-07-19T03:40:57.8424398Z  36.725451         #     expected: '1'
2022-07-19T03:40:57.8425119Z  36.725595         # {"type":"h1-accept","tid":46723,"seq":7,"conn-id":7,"sock":94919463877056,"conn":94919463946432,"conn-uuid":"7d0a1b0c-86a2-427e-8899-764723a5104d","time":1658202024830}
2022-07-19T03:40:57.8425745Z  36.725599         # {"type":"receive-request","tid":46723,"seq":8,"conn-id":7,"req-id":1,"http-version":257,"time":1658202024830}
2022-07-19T03:40:57.8426377Z  36.725602         # {"type":"receive-request-header","tid":46723,"seq":9,"conn-id":7,"req-id":1,"name-len":10,"value-len":15,"time":1658202024830}
2022-07-19T03:40:57.8427015Z  36.725605         # {"type":"receive-request-header","tid":46723,"seq":10,"conn-id":7,"req-id":1,"name-len":7,"value-len":4,"time":1658202024830}
2022-07-19T03:40:57.8427660Z  36.725608         # {"type":"receive-request-header","tid":46723,"seq":11,"conn-id":7,"req-id":1,"name-len":5,"value-len":1,"time":1658202024830}
2022-07-19T03:40:57.8428300Z  36.725610         # {"type":"receive-request-header","tid":46723,"seq":12,"conn-id":7,"req-id":1,"name-len":7,"value-len":4,"time":1658202024830}
2022-07-19T03:40:57.8428947Z  36.725613         # {"type":"receive-request-header","tid":46723,"seq":13,"conn-id":7,"req-id":1,"name-len":10,"value-len":11,"time":1658202024830}
2022-07-19T03:40:57.8429587Z  36.725615         # {"type":"receive-request-header","tid":46723,"seq":14,"conn-id":7,"req-id":1,"name-len":6,"value-len":3,"time":1658202024830}
2022-07-19T03:40:57.8430175Z  36.725617         # {"type":"send-response","tid":46723,"seq":15,"conn-id":7,"req-id":1,"status":200,"time":1658202024830}
2022-07-19T03:40:57.8430790Z  36.725628         # {"type":"send-response-header","tid":46723,"seq":16,"conn-id":7,"req-id":1,"name-len":14,"value-len":1,"time":1658202024830}
2022-07-19T03:40:57.8431486Z  36.725633         # {"type":"send-response-header","tid":46723,"seq":17,"conn-id":7,"req-id":1,"name-len":4,"value-len":29,"time":1658202024830}
2022-07-19T03:40:57.8432126Z  36.725636         # {"type":"send-response-header","tid":46723,"seq":18,"conn-id":7,"req-id":1,"name-len":12,"value-len":10,"time":1658202024830}
2022-07-19T03:40:57.8432759Z  36.725638         # {"type":"send-response-header","tid":46723,"seq":19,"conn-id":7,"req-id":1,"name-len":13,"value-len":29,"time":1658202024830}
2022-07-19T03:40:57.8433418Z  36.725641         # {"type":"send-response-header","tid":46723,"seq":20,"conn-id":7,"req-id":1,"name-len":4,"value-len":12,"time":1658202024830}
2022-07-19T03:40:57.8434041Z  36.725643         # {"type":"send-response-header","tid":46723,"seq":21,"conn-id":7,"req-id":1,"name-len":13,"value-len":5,"time":1658202024830}
2022-07-19T03:40:57.8434601Z  36.725646         # {"type":"socket-writev","tid":46723,"seq":22,"sock":94919463877056,"ret":236,"time":1658202024830}
2022-07-19T03:40:57.8435078Z  36.725648         # {"type":"h1-close","tid":46723,"seq":23,"conn-id":7,"time":1658202024831}
2022-07-19T03:40:57.8435537Z  36.725651         # {"type":"h1-close","tid":47013,"seq":24,"conn-id":2,"time":1658202025782}
2022-07-19T03:40:57.8435811Z  36.725930         1..3
2022-07-19T03:40:57.8436056Z  36.726035         # Looks like you failed 1 test of 3.
2022-07-19T03:40:57.8436412Z  36.726217     not ok 2 - with matched IP address
2022-07-19T03:40:57.8436783Z  36.726393     #   Failed test 'with matched IP address'
2022-07-19T03:40:57.8437188Z  36.726396     #   at t/90h2olog-selective-tracing.t line 222.
2022-07-19T03:40:57.8437502Z  36.726629     # killing h2olog[43874] with SIGTERM
2022-07-19T03:40:57.8437739Z  38.732811     1..2
2022-07-19T03:40:57.8437969Z  38.732953     # Looks like you failed 1 test of 2.
2022-07-19T03:40:57.8438300Z  38.733641 not ok 4 - h2olog -A=127.0.0.2

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions