`sent.sent_time - received.time` yields negative results

[FelixZY]

Brief description

I'm trying to make performance measures of DNS queries. When using the sent_time property, the resulting time measure will end up negative at times.

Environment

• Scapy version: 2.4.0, 2.4.1, 2.4.2, 2.4.3rc1
• Python version: 3.7
• Operating System: Ubuntu 18.04.2 LTS

How to reproduce

The problem is not consistent but tends to appear a few times per run when running the 16 "jobs" produced by the following data set:

dns_server: 8.8.8.8, 8.8.4.4, 1.1.1.1, 1.0.0.1
host: google.com, facebook.com
record: A, AAAA

Code used for query and time measurement

ans, unans = sr(
    IP(
        dst=job.dns_server
    )
    / UDP()
    / DNS(
        rd=1,
        qd=DNSQR(
            qname=job.host,
            qtype=job.record
        )
    ),
    retry=0,
    timeout=job.timeout.total_seconds(),
    verbose=False
)

query = ans[0][0]
answer = ans[0][1]

sent_time = datetime.fromtimestamp(query.sent_time)
response_time = datetime.fromtimestamp(answer.time)
rtt = response_time - sent_time

if rtt < timedelta(0):
    logger.warning(unindent(f"""Negative time for job!
    |Job: ({job})
    |
    |query.sent_time: {sent_time}
    |   timestamp: {query.sent_time}
    |
    |query.time: {datetime.fromtimestamp(query.time)}
    |   timestamp: {query.time}
    |
    |answer.time: {response_time}
    |   timestamp: {answer.time}
    |
    |rtt: {rtt.total_seconds()}
    |"""))

Actual result

2019-03-28 17:52:21 +0100 [WARNING](worker#25375): Negative time for job!
Job: (HoardJob(dns_server='8.8.4.4', host='facebook.com', record='A', timeout=datetime.timedelta(microseconds=500000)))

query.sent_time: 2019-03-28 17:52:21.329890
   timestamp: 1553791941.3298903

query.time: 2019-03-28 17:52:21.224104
   timestamp: 1553791941.224104

answer.time: 2019-03-28 17:52:21.294609
   timestamp: 1553791941.2946088

rtt: -0.035281

Expected result

• query.sent_time < answer.time
• rtt > 0
• query.sent_time=query.time (Possibly? Not sure what the distinction is supposed to be)

Edit: For future reference as I found this information hard to find at the time of writing:

time should be set when the packet is created (or dissected), whereas sent_time should be when it is sent (@gpotter2)

Related resources

I believe #1791 may be related. However, this issue appears for 2.4.0 as well.

[guedou]

It seems that you are using threads. Does this issue also occurs in a single process?
Also, could you provide a complete code that triggers the issue. Thanks.

[FelixZY]

The code is indeed running using the multiprocessing module, sorry for not mentioning that.

Running some quick tests on another machine (debian stretch running in docker container on surface pro 5 i5), does not seem to trigger any errors for the provided dataset for a single background thread (best I can do without complete rewrite. Main thread is not interacting with scapy during this time), nor does 3 background threads seem to trigger the issue. 6 does however, as does the original 11 (no. background threads are calculated using os.cpu_count() - 1).

Although the code in question is meant to be used for a thesis project, we are not allowed to reveal too much at this time. Are there any specific details you are interested in?

EDIT
A more complete sample of the background thread:

def __perform_hoard(queue: multiprocessing.Queue, write_queue: multiprocessing.Queue):
    # Do not listen to keyboard interrupt in subprocess
    signal.signal(signal.SIGINT, signal.SIG_IGN)

    logger = logging.LoggerAdapter(logging.getLogger("worker"), {"pid": os.getpid()})

    try:
        logger.debug("Worker started")

        while True:
            job = queue.get()  # type: HoardJob

            if job is None:
                break

            logger.debug(f"Received job ({job})")

            try:
                ans, unans = sr(
                    IP(
                        dst=job.dns_server
                    )
                    / UDP()
                    / DNS(
                        rd=1,
                        qd=DNSQR(
                            qname=job.host,
                            qtype=job.record
                        )
                    ),
                    retry=0,
                    timeout=job.timeout.total_seconds(),
                    verbose=False
                )

                try:
                    query = ans[0][0]  # type: IP
                    answer = ans[0][1]  # type: IP
                except IndexError:
                    raise TimeoutError(f"No response was received for job ({job})") from None

                logger.debug(f"Job ({job}) trace:\n{answer.show(dump=True)}")

                if DNS not in answer or ICMP in answer:
                    raise KeyError(f"Job ({job}) did not return a valid DNS response")

                sent_time = datetime.fromtimestamp(query.sent_time)
                response_time = datetime.fromtimestamp(answer.time)
                rtt = response_time - sent_time

                # The following is related to scapy issue [#1952](https://github.com/secdev/scapy/issues/1952)
                if rtt < timedelta(0):
                    logger.error(unindent(f"""Negative time for job!
                    |Job: ({job})
                    |
                    |query.sent_time: {sent_time}
                    |   timestamp: {query.sent_time}
                    |
                    |query.time: {datetime.fromtimestamp(query.time)}
                    |   timestamp: {query.time}
                    |
                    |answer.time: {response_time}
                    |   timestamp: {answer.time}
                    |
                    |rtt: {rtt.total_seconds()}
                    |"""))

[guedou]

I can confirm that a similar code without threads did not exhibit any issue after ~4500 run.

Can you try add some data to your query for example by setting TCP.sport and DNS.id to RandShort(). I think that nothing we can do on our side can make your code work.

[FelixZY]

I will test that when I get home; in the meanwhile this does seem to be a problem with multiple threads. Have you tested running your aforementioned test with 5+ threads?

[guedou]

I do not believe that this not related to Scapy so I won’t investigate more until you test with the random values.

[FelixZY]

Back on original machine; using the following setup does not appear to result in negative rtts:

ans, unans = sr(
    IP(
        dst=job.dns_server
    )
    / UDP(
        sport=RandShort()
    )
    / DNS(
        id=RandShort(),
        rd=1,
        qd=DNSQR(
            qname=job.host,
            qtype=job.record
        )
    ),
    retry=0,
    timeout=job.timeout.total_seconds(),
    verbose=False
)

Any idea why this setup yields different results?

[guedou]

You were sending identical packet (identical UDP sport and DNS id among other things) from different threads =)
Scapy uses default values that work for most usages, but one needs to be careful for specific usages.

I am glad your tool now works!

[FelixZY]

Thank you for your help, this does seem to fix our problems!

Although this may be low priority now, there are still a few things I wonder about:

• If identical packets were sent, does that mean that it was answer.time that was incorrect (since scapy must have known which packet was sent)
• How come the packets are identical when the exact combination of host, record and dns_server is only sent once and is not the same across threads?
• Should not the default values of scapy be chosen as to avoid issues like this, i.e. to allow usage in a multithreaded environment?
• Is there any documentation available where the extra requirements for a multithreaded application are mentioned?

[gpotter2]

It’s not related to scapy specifically, nor multithreading: to match DNS answers, you’re supposed to match their IDs.

Scapy defaults all IDs to 0. We could default them to RandShort() but that would break many tests, and it’s counter intuitive that raw(DNS()) != raw(DNS()).

In non-multithreaded mode, scapy sends packet THEN waits for the answers. In multithreaded mode, if you keep all the IDs 0, any answer will match any packet from any thread, as they run asynchronously. If you set a RandShort to each one, it will avoid such cases

[FelixZY]

I can see the logic in that; although I would still expect default values to be thread safe or to find explicit notes on this somewhere.

A final question: the final application will run many more queries. My understanding is that the DNS() id attribute is the important piece of the puzzle here. Is there not a risk that RandShort will generate duplicate ids (although very small)? Should it not in the case be safer to keep some sort of shared counter to ensure separate DNS ids?

Thank you again for all your help and now also patience in this matter.

[gpotter2]

It’s up to you to follow the RFC 😄
https://tools.ietf.org/html/rfc5452#section-9.2

Resolver implementations MUST:
[...]
- Use an unpredictable query ID for outgoing queries, utilizing the
      full range available (0-65535).

Chances are incredibly low for 2 packets to be sent with the same ID in a time frame short enough for conflicts to happen