possible clock skew bug #1482

Open
adriancole opened this Issue Jan 11, 2017 · 4 comments

Projects

None yet

1 participant

@adriancole
Contributor

The following trace (which is on the same host), ends up being skewed in latest zipkin, but not an older version.

current version:
screen shot 2017-01-11 at 4 06 36 pm

older version (1.13 but probably later would still work):
screen shot 2017-01-11 at 4 06 58 pm

curl -s localhost:9411/api/v1/spans -H'Content-Type: application/json' -d '[
  {
    "traceId": "ef6b0ede64a8d347",
    "id": "1b5047ceaaa0142f",
    "name": "print-date",
    "parentId": "2dcfafadb8f566bb",
    "timestamp": 1484121797462000,
    "duration": 21434,
    "binaryAnnotations": [
      {
        "key": "lc",
        "value": "unknown",
        "endpoint": {
          "serviceName": "backend",
          "ipv4": "127.0.0.1",
          "port": 9000
        }
      },
      {
        "key": "mvc.controller.class",
        "value": "Backend",
        "endpoint": {
          "serviceName": "backend",
          "ipv4": "127.0.0.1",
          "port": 9000
        }
      },
      {
        "key": "mvc.controller.method",
        "value": "printDate",
        "endpoint": {
          "serviceName": "backend",
          "ipv4": "127.0.0.1",
          "port": 9000
        }
      }
    ]
  },
  {
    "traceId": "ef6b0ede64a8d347",
    "id": "2dcfafadb8f566bb",
    "name": "http:/api",
    "parentId": "8a30f690953c3b64",
    "annotations": [
      {
        "timestamp": 1484121797448000,
        "value": "sr",
        "endpoint": {
          "serviceName": "backend",
          "ipv4": "127.0.0.1",
          "port": 9000
        }
      },
      {
        "timestamp": 1484121797501000,
        "value": "ss",
        "endpoint": {
          "serviceName": "backend",
          "ipv4": "127.0.0.1",
          "port": 9000
        }
      }
    ]
  },
  {
    "traceId": "ef6b0ede64a8d347",
    "id": "2dcfafadb8f566bb",
    "name": "http:/api",
    "parentId": "8a30f690953c3b64",
    "timestamp": 1484121797368000,
    "duration": 120000,
    "annotations": [
      {
        "timestamp": 1484121797368000,
        "value": "cs",
        "endpoint": {
          "serviceName": "frontend",
          "ipv4": "127.0.0.1",
          "port": 8081
        }
      },
      {
        "timestamp": 1484121797488000,
        "value": "cr",
        "endpoint": {
          "serviceName": "frontend",
          "ipv4": "127.0.0.1",
          "port": 8081
        }
      }
    ],
    "binaryAnnotations": [
      {
        "key": "http.host",
        "value": "localhost",
        "endpoint": {
          "serviceName": "frontend",
          "ipv4": "127.0.0.1",
          "port": 8081
        }
      },
      {
        "key": "http.method",
        "value": "GET",
        "endpoint": {
          "serviceName": "frontend",
          "ipv4": "127.0.0.1",
          "port": 8081
        }
      },
      {
        "key": "http.path",
        "value": "/api",
        "endpoint": {
          "serviceName": "frontend",
          "ipv4": "127.0.0.1",
          "port": 8081
        }
      },
      {
        "key": "http.url",
        "value": "http://localhost:9000/api",
        "endpoint": {
          "serviceName": "frontend",
          "ipv4": "127.0.0.1",
          "port": 8081
        }
      },
      {
        "key": "sa",
        "value": true,
        "endpoint": {
          "serviceName": "frontend",
          "ipv4": "127.0.0.1",
          "port": 8081
        }
      }
    ]
  },
  {
    "traceId": "ef6b0ede64a8d347",
    "id": "8a30f690953c3b64",
    "name": "call-backend",
    "parentId": "ef6b0ede64a8d347",
    "timestamp": 1484121797351000,
    "duration": 165050,
    "binaryAnnotations": [
      {
        "key": "lc",
        "value": "unknown",
        "endpoint": {
          "serviceName": "frontend",
          "ipv4": "127.0.0.1",
          "port": 8081
        }
      },
      {
        "key": "mvc.controller.class",
        "value": "Frontend",
        "endpoint": {
          "serviceName": "frontend",
          "ipv4": "127.0.0.1",
          "port": 8081
        }
      },
      {
        "key": "mvc.controller.method",
        "value": "callBackend",
        "endpoint": {
          "serviceName": "frontend",
          "ipv4": "127.0.0.1",
          "port": 8081
        }
      }
    ]
  },
  {
    "traceId": "ef6b0ede64a8d347",
    "id": "ef6b0ede64a8d347",
    "name": "http:/",
    "timestamp": 1484121797338000,
    "duration": 179732,
    "annotations": [
      {
        "timestamp": 1484121797338000,
        "value": "sr",
        "endpoint": {
          "serviceName": "frontend",
          "ipv4": "127.0.0.1",
          "port": 8081
        }
      },
      {
        "timestamp": 1484121797518000,
        "value": "ss",
        "endpoint": {
          "serviceName": "frontend",
          "ipv4": "127.0.0.1",
          "port": 8081
        }
      }
    ]
  }
]'
@adriancole
Contributor

cc @fedj @marcingrzejszczak I'm taking a look now...

@adriancole
Contributor

actually span 2dcfafadb8f566bb is invalid..

  • the server send is 1484121797501000
  • the client receive is 1484121797488000 (13ms before the server sent the request!)

still, we shouldn't adjust because the endpoints are of the same host

@adriancole adriancole added a commit that referenced this issue Jan 11, 2017
@adriancole adriancole Kicks out instead of correcting skew on single-host spans
An instrumentation glitch can look like clock skew. This kicks out when
RPC annotations all belong to the same host.

This also backfills tests.

See #1482
9e709a3
@adriancole
Contributor
@adriancole
Contributor

after dinner I'll look even more closely to see if there's a way to detect this (without cheating like assuming bugs only happen on loopback spans :P)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment