search

ASCOMInitiative / ConformU

ConformU is a cross-platform tool to validate that Alpaca Devices and ASCOM Drivers conform to the ASCOM interface specification. It supersedes the original Windows based Conform application.
11 stars 2 forks source link

Provide a way to match ConformU test outcomes to server logs #19

Closed RReverser closed 2 months ago

RReverser commented 2 months ago

Right now, when running tests, one has to manually match logs written by their server to logs provided by ConformU and more or less guess how they correspond based on URLs hit.

This gets pretty inconvenient and time-consuming when you're trying to use verbose server logs to match a couple of test failures somewhere in the middle of ConformU suit.

Could ConformU provide some mechanism to simplify this? Perhaps it could print ServerTransactionID as part of the test outcome (and any logs issued during said test) - after all, that field exists pretty much for this purpose, matching transactions between client and server? Or should it add some custom test-only field?

Peter-Simpson commented 2 months ago

Have you tried enabling Debug and Trace Alpaca Calls? This does generate lots of output, but raw Alpaca responses are shown, which include ServerTransactionID.

I don't think this is a feature that I'm going to be able to add I'm afraid. ConformU tests are completely agnostic as to whether the device is Alpaca or COM, so adding special behaviour for Alpaca devices is going to be challenging, particularly as there are over 1000 OK/ISSUE responses that I'd have to deal with.

Best wishes, Peter

image

image

RReverser commented 2 months ago

so adding special behaviour for Alpaca devices is going to be challenging, particularly as there are over 1000 OK/ISSUE responses that I'd have to deal with.

Oh I didn't think you'd do this by hand for each response, but rather in a centralised way in the logger implementation, similarly to how it adds timestamps.

Have you tried enabling Debug and Trace Alpaca Calls? This does generate lots of output, but raw Alpaca responses are shown, which include ServerTransactionID.

Yeah maybe I'll have to do that, but as you said, it's fairly verbose.

For context, I'm not actually trying to match logs by hand, but rather parsing ConformU output (as a poor man's replacement for https://github.com/ASCOMInitiative/ConformU/issues/5) in my test runner, and I want to automatically find test failure and show server logs + ConformU logs only for failures side by side.

Right now this is challenging due to asynchronous nature of network requests and no obvious way to match each server log to a specific test, so I have to show all the server logs instead, whether they're related to the failing test or to other successful tests.

Perhaps I could parse those JSON response: ... lines meanwhile like you said... just thought I'd raise an issue in case you have better ideas for managing this centrally from the logger.

Peter-Simpson commented 2 months ago

Unfortunately the Alpaca implementation is hidden from Conform, which works with the device interfaces that are common across COM and Alpaca. This means that all COM/Alpaca implementation details are hidden.

I understand your use case but don't think I'm able to help on this occasion.

Best wishes, Peter

RReverser commented 2 months ago

Unfortunately the Alpaca implementation is hidden from Conform, which works with the device interfaces that are common across COM and Alpaca. This means that all COM/Alpaca implementation details are hidden.

I see that at least AlpacaProtocolTestManager makes its own HTTP requests via centralised CallApi / SendToDevice methods, so if I modified those methods to either send a test ID to the server via some non-standard header, or stored a ServerTransactionID from the responses for the logger, then the Alpaca tests would automatically provide the required information.

That doesn't help with general conformance checks, as you said, but perhaps better than nothing...

What if we modified ASCOM Remote itself to print the ServerTransactionID in debug mode instead? Then it could print the transaction IDs from both Alpaca-specific and general Conform tests.

Peter-Simpson commented 2 months ago

I'm sorry Ingvar but I simply don't have time to pursue this right now. I have another Platform RC to release and then further work and tests to run to create a production release. I'm also in the middle of finalising the Library and ConformU.

Right now I have to prioritise the Platform and larger ASCOM community, so I'm going to close this proposal as not planned.

RReverser commented 2 months ago

OK no worries.

RReverser commented 1 month ago

Just wanted to share an update - this was tricky, but actually found a way to implement streaming log parsing just right, and now my own logs and ConformU logs are shown interleaved just like I wanted.

alpacaprotocol test example:

...
ERROR    handle_alpaca_request [ 50.9µs | 29.08% / 100.00% ] path: "/api/v1/camera/0/biny" | client_id: 123456 | client_transaction_id: 67890 | server_transaction_id: 66
DEBUG    ┝━ 🐛 [debug]: Received request | params: Put({"BinY": "1", "ExtraParameter": "ExtraValue"})
WARN     ┝━ 🚧 [warn]: Unused parameters: ["ExtraParameter"]
ERROR    ┕━ Alpaca transaction [ 36.1µs | 70.92% ] action: "biny" | client_transaction_id: 60 | client_id: 395962223
DEBUG       ┝━ 🐛 [debug]: Sending request | method: Put | params: OpaqueParams { bin_y: 1 } | base_url: http://127.0.0.1:32323/api/v1/camera/0/
DEBUG       ┕━ 🐛 [debug]: Received response
TRACE    📍 [trace]: ClientTransactionID is correctly cased | method: "BinY" | outcome: "OK" | http_method: "PUT" | test_kind: AlpacaProtocol
TRACE    📍 [trace]: ServerTransactionID is correctly cased | method: "BinY" | outcome: "OK" | http_method: "PUT" | test_kind: AlpacaProtocol
TRACE    📍 [trace]: ErrorNumber is correctly cased | method: "BinY" | outcome: "OK" | http_method: "PUT" | test_kind: AlpacaProtocol
TRACE    📍 [trace]: ErrorMessage is correctly cased | method: "BinY" | outcome: "OK" | http_method: "PUT" | test_kind: AlpacaProtocol
TRACE    📍 [trace]: The expected ClientTransactionID was returned: 67890 | test: "Parameter BinY (Good casing + extra parameter)" | method: "BinY" | outcome: "OK" | http_method: "PUT" | test_kind: AlpacaProtocol
TRACE    📍 [trace]: The ServerTransactionID was 1 or greater: 66 | test: "Parameter BinY (Good casing + extra parameter)" | method: "BinY" | outcome: "OK" | http_method: "PUT" | test_kind: AlpacaProtocol
TRACE    📍 [trace]: Received HTTP status 200 (OK) as expected. | test: "Parameter BinY (Good casing + extra parameter)" | method: "BinY" | outcome: "OK" | http_method: "PUT" | test_kind: AlpacaProtocol
...

Conformance test example:

...
ERROR    handle_alpaca_request [ 58.9µs | 31.24% / 100.00% ] path: "/api/v1/camera/0/setccdtemperature" | client_id: 1 | client_transaction_id: 85 | server_transaction_id: 481
DEBUG    ┝━ 🐛 [debug]: Received request | params: Get({})
ERROR    ┝━ Alpaca transaction [ 40.5µs | 68.76% ] action: "setccdtemperature" | client_transaction_id: 443 | client_id: 395962223
DEBUG    │  ┝━ 🐛 [debug]: Sending request | method: Get | params: OpaqueParams | base_url: http://127.0.0.1:32323/api/v1/camera/0/
DEBUG    │  ┕━ 🐛 [debug]: Received response
ERROR    ┕━ 🚨 [error]: Alpaca method returned an error | error: ASCOM error NOT_IMPLEMENTED: Property read SetCCDTemperature is not implemented in this driver.
TRACE    📍 [trace]: Optional member returned a NotImplementedException error. | method: "SetCCDTemperature Read" | outcome: "OK" | test_kind: Conformance
DEBUG    🐛 [debug]: Exception detail: ASCOM.NotImplementedException: Property read SetCCDTemperature is not implemented in this driver. is not implemented in this driver. | method: "SetCCDTemperature Read" | outcome: "DEBUG" | test_kind: Conformance
...

My only regret is that parsing logs is pretty fragile, so I still want to find some time and work on #5, but at least happy to see that timing finally works for correct interleaving.