Common Logs Explained

The following are the examples of .Net logs you'll find for some common scenarios

1. Validation Logs

Most of the validation problems are because of the mismatch between market-associated specifiers and which specifiers are expected based on the market description. This is just a log entry; the message is processed and dispatched to the user code normally.

Example

2023-06-07 14:54:46,260  INFO	 [19]	 FeedMessageValidator	 Specifiers check failed. Producer=5, market[id=877], Required:inningnr,total,maxovers, Actual:matchinningnr,maxovers,total,inningnr
2023-06-07 14:54:46,264	 WARN	 [19]	 OddsFeedSession	 Live: Problems were detected while validating message=[odds_change ProducerId=5, EventId=sr:match:40481547, GeneratedAt=1686141350193, ReceivedAt=1686142486152, Age=1135959], but the message is still eligible for further processing.

2. FeedExt Raw Data Processing Logs

When subscribing to raw data (feed and API) utilizing FeedExt instead of a normal Feed instance, SDK logs how long it took in user code to process the raw message. Long times could indicate problems in user code and will slow down message processing in the SDK pipeline.

Example

2023-05-16 13:08:59,474	 INFO	 [com:5671)]	 FeedExt	 Dispatching raw feed message [prematch]: odds_change for event sr:match:39497539 (173202793) took 1 ms.

3. RabbitMQ Message Logs

Each feed message is logged when picked up by the SDK from the underlying rabbit mq library. GeneratedAt is the timestamp when the message was created on the server side, ReceivedAt when it was picked up by the SDK (when it entered SDK processing pipeline) and Age the difference in ms. Depends on the message type it may or may not have associated EventId.

Example

2023-05-16 13:08:32,571	 INFO	 [com:5671)]	 RabbitMqMessageReceiver	 Message received. Message=[alive ProducerId=5, GeneratedAt=1684235311215, ReceivedAt=1684235312545, Age=1330]. 
2023-05-16 13:08:32,571	 INFO	 [com:5671)]	 RabbitMqMessageReceiver	 Message received. Message=[odds_change ProducerId=3, EventId=sr:match:41286131, GeneratedAt=1684235310565, ReceivedAt=1684235312544, Age=1979].    

4. Producer Recovery Logs

Handling recovery process and monitoring producer state is complex mechanism within SDK. It produces log messages for every change between states, with relevant data. Some of the checks are done on every message, and some on timer (in case no message arrive).

On timer (every 10s) it also checks the state of the producer. That is the state as sdk sees it, and does not reflect the state of the server producer.

Example

2023-05-16 13:08:35,108	 INFO	 [com:5671)]	 ProducerRecoveryManager	 Recovery with requestId=173202825 for producer=15 completed in 527 ms. 
2023-05-16 13:08:35,108	 INFO	 [com:5671)]	 ProducerRecoveryManager	 VBI Status changed from Started to Completed. 

5. Internal state of producer

When criteria is met which would cause the change of sdk internal state of producer, logs can provide insight what is the reason for change.

Example

2023-05-16 13:09:46,972	 WARN	 [16]	 ProducerRecoveryManager	 Producer id=9: no alive messages arrived since 16/05/2023 13:08:23. New recovery will be done. 
2023-05-16 13:09:46,972	 INFO	 [16]	 ProducerRecoveryManager	 Producer=9: Recovery operation skipped. Last done at 16/05/2023 13:09:26

6. Timer-Based Checks:

On timer the state of each available producer is checked. Tracking is also done for each configured session.

• The "age" specifies the time elapsed from message generation (by the feed) and the current time (i.e. current_time - message_generation_time).

• The "latency" specifies the time elapsed message generation (by the feed) and when it was received by the SDK(i.e. message_receival_time - message_generation_time).

Log entry explanation: The entry can be break-down into two parts:

• Producer info: 1(LO):[IsUp=False,Timestamp=01.01.0001-00:00:00.000(Started)

  • 1(LO) - the id and name of the producer

  • IsUp=False - whether the producer is marked as "up" or "down" at a moment the entry was written

  • Timestamp=01.01.0001-00:00:00.000 - The "Timestamp before disconnect" - indicating the time from which the recovery has to be made if the SDK is restarted. Value 01.01.0001-00:00:00.000 is a min date/time that can be represented in .net framework and indicates that a full recovery needs to be done.

  • (Started) - internal state of the producer. The following values are defined:

    • NotStarted - the recovery has not been started yet

    • Started - the recovery has been started and is still in progress

    • Completed - the recovery has been completed and the status of the producer is up-to-date

    • Error - the recovery has failed and will be re-started when the next alive is received from the feed

    • FatalError - the recovery has failed with un-recoverable error and will not be attempted again. This only happens when the recovery timestamp is set to much in the past and therefore cannot be initiated.

    • Delayed - the recovery has been completed and the status of the producer is up-to-date, but the user is falling behind with message processing (processing is to slow).

• timing info: [[Ping(Ok):age=00:00:01,918],[IsBehind(True):Alive(s)[all:age=00:08:17,088],NonAlives[all:latency=00:05:20,859]]].

  • Ping(Ok) - whether the producer is behaving as expected (based on the age of the last alive message being smaller than maxInactivitySeconds config property

  • age=00:00:01,918 - the age of the last alive message received on a session which is not affected by other messages

  • IsBehind(True) - specifies whether the user is falling behind on message processing. The producer is considered as "behind" when either latency or age of any message is larger than maxInactivitySeconds

  • Alive(s)[all:age=00:08:17,088] - the age of last alive message received on user created sessions. If the user created more than one session, the output will specify multiple ages

  • NonAlives[all:latency=00:05:20,859] - the latency of last non-alive (bet_stop, odds_change) message received on user created sessions. If the user created more than one session, the output will specify multiple latencies

  Example

2023-05-16 13:10:17,277	 INFO	 [11]	 ProducerRecoveryManager	 Status check: Producer=5(PremiumCricket):[IsUp=False,Timestamp=16.05.2023-11:28:23.693](Started), Timing Info=[[Ping(Ok):age=00:00:06.453],[IsBehind(True):Alive(s)[prematch:age=00:01:46.062,live:age=00:01:53.498],NonAlives[prematch:latency=00:00:27.918,live:latency=00:00:00.000]]]     

7. Recovery Request Logs

Closely related is also RecoveryRequestIssuer. When new API call for recovery request needs to be made, it logs which kind of recovery is done.

Example

2023-05-16 13:08:36,715	 INFO	 [23]	 RecoveryRequestIssuer	 Recovery since after timestamp for Producer=8(VBL):[IsUp=False,Timestamp=16.05.2023-11:28:23.693], RequestId=173202830, After=16/05/2023 11:28:23 succeeded. 
2023-05-16 13:08:38,653	 INFO	 [15]	 RecoveryRequestIssuer	 Full odds recovery for Producer=17(VCI):[IsUp=False,Timestamp=01.01.0001-00:00:00.000], RequestId=173202841 succeeded.  

8. API Call Logs (DataRouterManager)

DataRouterManager handles majority of API calls. The log message shows which endpoint was called, parameters and how long it took. Taken time is for the full method execution and not just pure HttpClient request (for that associated log entry can be checked in RestTraffic log). Saving indicates how long the sdk needed to distribute received data between internal caches. This is logged only if it takes longer then 20ms.

Example

2023-05-18 13:08:35,510	 INFO	 [27]	 DataRouterManager	 Executing GetSportEventsForDateAsync for date=18/05/2023 and culture=en took 1711 ms. 
2023-05-18 13:09:03,438	 INFO	 [23]	 DataRouterManager	 Executing GetSportEventSummaryAsync for id=sr:match:39463751 and culture=en took 103 ms.
2023-05-18 13:09:19,873	 INFO	 [23]	 DataRouterManager	 Executing GetSportEventSummaryAsync for id=sr:season:95457 and culture=es took 106 ms. Saving took 205 ms.  

9. RestTraffic Logs

All the API calls are logged in RestTraffic. Based on the log level set by the user, the logs can be different. On info level just traceId, url and duration is logged. On debug level also the actual xml received from the API is logged. Debug level is recommended during integration period. When exception happens all the data is logged. INFO log example

2025-03-25 15:03:00,789	 INFO	 [17]	 RestTraffic	 TraceId: 2a546bb8-b73a-4edc-8861-5a4e0cc811dc GET: https://stgapi.betradar.com/v1/descriptions/en/match_status.xml took 235 ms 
2025-03-25 15:03:00,850	 INFO	 [17]	 RestTraffic	 TraceId: 98a9d20f-f43e-4b84-8449-ecf3cfbbf187 GET: https://stgapi.betradar.com/v1/descriptions/void_reasons.xml took 40 ms 

DEBUG log example

2025-03-25 15:00:00,693	 DEBUG	 [16]	 RestTraffic	 TraceId: 26911f24-3db9-4d2a-94c8-5f045e82ab7d GET: https://stgapi.betradar.com/v1/descriptions/void_reasons.xml took 41 ms Response: 

<?xml version="1.0" encoding="UTF-8" standalone="yes"?><void_reasons_descriptions response_code="OK"><void_reason id="0" description="OTHER"/><void_reason id="1" description="NO_GOALSCORER"/><void_reason id="2" description="CORRECT_SCORE_MISSING"/><void_reason id="3" description="RESULT_UNVERIFIABLE"/><void_reason id="4" description="FORMAT_CHANGE"/><void_reason id="5" description="CANCELLED_EVENT"/><void_reason id="6" description="MISSING_GOALSCORER"/><void_reason id="7" description="MATCH_ENDED_IN_WALKOVER"/><void_reason id="8" description="DEAD_HEAT"/><void_reason id="9" description="RETIRED_OR_DEFAULTED"/><void_reason id="10" description="EVENT_ABANDONED"/><void_reason id="11" description="EVENT_POSTPONED"/><void_reason id="12" description="INCORRECT_ODDS"/><void_reason id="13" description="INCORRECT_STATISTICS"/><void_reason id="14" description="NO_RESULT_ASSIGNABLE"/><void_reason id="15" description="CLIENT_SIDE_SETTLEMENT_NEEDED"/><void_reason id="16" description="STARTING_PITCHER_CHANGED"/></void_reasons_descriptions> 

2025-03-25 15:00:00,738	 DEBUG	 [9]	 RestTraffic	 TraceId: eecf0f4d-d0ba-42dd-9f04-68bc968df7b0 GET: https://stgapi.betradar.com/v1/descriptions/betstop_reasons.xml took 44 ms Response: 

<?xml version="1.0" encoding="UTF-8" standalone="yes"?><betstop_reasons_descriptions response_code="OK"><betstop_reason id="0" description="UNKNOWN"/><betstop_reason id="1" description="POSSIBLE_GOAL"/><betstop_reason id="2" description="POSSIBLE_RED_CARD"/><betstop_reason id="3" description="SCOUT_LOST"/><betstop_reason id="4" description="POSSIBLE_GOAL_HOME"/><betstop_reason id="5" description="POSSIBLE_GOAL_AWAY"/></betstop_reasons_descriptions

10. SportEventStatus Logs

Receiving SportEventStatus from timeline endpoint can be cached or ignored based on user configuration property IgnoreBetPalTimelineSportEventStatus (default false). As name implies only SportEventStatus received in response from timeline endpoint for events associated with BetPal producer will be ignored.

Example

2025-03-25 13:08:35,510	 INFO	 [27]  SportEventStatusCache  Received SES for {EventId} from {Source} with EventStatus:{SportEventStatus} (timeline ignored) {StatusOnEvent}