missing trailing string terminator?

[jorhett]

I'm not certain of this one, so I'm going to leave it to the string experts. I've seen that when calling http_connection twice in a routine that's called multiple times it's common to get a block of memory with the same address, and sometimes (but not always) the content of the previous query still there.

It doesn't appear to be causing a problem because we're using the length returned to parse it in ssl_recv() but my nitpicky sanity says that if we terminated the returned string with a null then strlen() and other features would work consistently.

Here's an example of what I was seeing:

Jan 12 21:54:52  inadyn[60330] <Info>: Id query, initiating HTTPS ...
Jan 12 21:54:52  inadyn[60330] <Info>: Id query, connecting to api.cloudflare.com([2606:4700:300a::6813:c11d]:443)
Jan 12 21:54:52  inadyn[60330] <Debug>: Certificate OK
Jan 12 21:54:52  inadyn[60330] <Info>: SSL server cert subject: C=US,ST=CA,L=San Francisco,O=CloudFlare\, Inc.,CN=api.cloudflare.com
Jan 12 21:54:52  inadyn[60330] <Info>: SSL server cert issuer: C=US,ST=CA,L=San Francisco,O=CloudFlare\, Inc.,CN=CloudFlare Inc ECC CA-2
Jan 12 21:54:52  inadyn[60330] <Debug>: Request:
    GET /client/v4/zones?name=netconsonance.com HTTP/1.0
    Host: api.cloudflare.com
    User-Agent: inadyn/2.6-dev https://github.com/troglobit/inadyn/issues
    Accept: */*
    Authorization: Bearer zdIIlxEdQ3ho**lg6k5aL6BoqJFsYgf
    Content-Type: application/json

Jan 12 21:54:52  inadyn[60330] <Debug>: Successfully sent HTTPS request!
Jan 12 21:54:52  inadyn[60330] <Info>: reply length: 1189
Jan 12 21:54:52  inadyn[60330] <Info>:body = 2558: 
        HTTP/1.1 200 OK
    Date: Mon, 13 Jan 2020 05:54:52 GMT
    Content-Type: application/json
    Connection: close
    Set-Cookie: __cfduid=dc6b******4c2c******561700c469c561578894892; expires=Wed, 12-Feb-20 05:54:52 GMT; path=/; domain=.api.cloudflare.com; HttpOnly; SameSite=Lax
    CF-Ray: 55451e386d609316-SJC
    Cache-Control: no-store, no-cache, must-revalidate, post-check=0, pre-check=0
    Expires: Sun, 25 Jan 1981 05:00:00 GMT
    Strict-Transport-Security: max-age=31536000, max-age=31536000
    CF-Cache-Status: DYNAMIC
    Expect-CT: max-age=604800, report-uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct"
    Pragma: no-cache
    Served-In-Seconds: 0.044
    X-Content-Type-Options: nosniff
    X-Frame-Options: SAMEORIGIN
    Server: cloudflare

    {"result":[{"id":"aad8dfa1218ae29dbdfe5fa9569cb682","name":"netconsonance.com","status":"pending","paused":false,"type":"full","development_mode":0,"name_servers":["beau.ns.cloudflare.com","colette.ns.cloudflare.com"],"original_name_servers":["ns-cloud-a1.googledomains.com","ns-cloud-a2.googledomains.com","ns-cloud-a3.googledomains.com","ns-cloud-a4.googledomains.com"],"original_registrar":"google llc (id: 895)","original_dnshost":null,"modified_on":"2020-01-13T05:24:30.488051Z","created_on":"2020-01-11T11:25:38.525131Z","activated_on":null,"meta":{"step":2,"wildcard_proxiable":false,"custom_certificate_quota":0,"page_rule_quota":3,"phishing_detected":false,"multiple_railguns_allowed":false},"owner":{"id":"409a04f8fc53f28091ce9f33a306ca7d","type":"user","email":"jrhett@netconsonance.com"},"account":{"id":"78cc6d0120b89d66f65d5ee57914243c","name":"jrhett@netconsonance.com"},"permissions":["#access:edit","#access:read","#analytics:read","#app:edit","#auditlogs:read","#billing:edit","#billing:read","#cache_purge:edit","#dns_records:edit","#dns_records:read","#lb:edit","#lb:read","#legal:edit","#legal:read","#logs:edit","#logs:read","#member:edit","#member:read","#organization:edit","#organization:read","#ssl:edit","#ssl:read","#stream:edit","#stream:read","#subscription:edit","#subscription:read","#waf:edit","#waf:read","#webhooks:edit","#webhooks:read","#worker:edit","#worker:read","#zone:edit","#zone:read","#zone_settings:edit","#zone_settings:read"],"plan":{"id":"0feeeeeeeeeeeeeeeeeeeeeeeeeeeeee","name":"Free Website","price":0,"currency":"USD","frequency":"","is_subscribed":true,"can_subscribe":false,"legacy_id":"free","legacy_discount":false,"externally_managed":false}}],"result_info":{"page":1,"per_page":20,"total_pages":1,"count":1,"total_count":1},"success":true,"errors":[],"messages":[]}
Jan 12 21:54:52  inadyn[60330] <Debug>: Successfully received HTTPS response (2558 bytes)!
Jan 12 21:54:52  inadyn[60330] <Debug>: Cloudflare Zone: 'netconsonance.com' Id: aad8dfa1218ae29dbdfe5fa9569cb682

Jan 12 21:54:52  inadyn[60330] <Info>: Id query, initiating HTTPS ...
Jan 12 21:54:52  inadyn[60330] <Info>: Id query, connecting to api.cloudflare.com([2606:4700:300a::6813:c11d]:443)
Jan 12 21:54:52  inadyn[60330] <Debug>: Certificate OK
Jan 12 21:54:52  inadyn[60330] <Info>: SSL server cert subject: C=US,ST=CA,L=San Francisco,O=CloudFlare\, Inc.,CN=api.cloudflare.com
Jan 12 21:54:52  inadyn[60330] <Info>: SSL server cert issuer: C=US,ST=CA,L=San Francisco,O=CloudFlare\, Inc.,CN=CloudFlare Inc ECC CA-2
Jan 12 21:54:52  inadyn[60330] <Debug>: Request:
    GET /client/v4/zones/aad8dfa1218ae29dbdfe5fa9569cb682/dns_records?type=AAAA&name=glamdring.dogspa.netconsonance.com HTTP/1.0
    Host: api.cloudflare.com
    User-Agent: inadyn/2.6-dev https://github.com/troglobit/inadyn/issues
    Accept: */*
    Authorization: Bearer zdIIlxEdQ3ho**lg6k5aL6BoqJFsYgf
    Content-Type: application/json

Jan 12 21:54:52  inadyn[60330] <Debug>: Successfully sent HTTPS request!
Jan 12 21:54:53  inadyn[60330] <Info>: body = 2568:
        HTTP/1.1 200 OK
    Date: Mon, 13 Jan 2020 05:54:53 GMT
    Content-Type: application/json
    Connection: close
    Set-Cookie: __cfduid=d3bbe3****89d1****ae439a40bdb56be1578894893; expires=Wed, 12-Feb-20 05:54:53 GMT; path=/; domain=.api.cloudflare.com; HttpOnly; SameSite=Lax
    CF-Ray: 55451e399b1351ce-SJC
    Cache-Control: no-store, no-cache, must-revalidate, post-check=0, pre-check=0
    Expires: Sun, 25 Jan 1981 05:00:00 GMT
    Strict-Transport-Security: max-age=31536000, max-age=31536000
    CF-Cache-Status: DYNAMIC
    Expect-CT: max-age=604800, report-uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct"
    Pragma: no-cache
    Served-In-Seconds: 0.041
    X-Content-Type-Options: nosniff
    X-Frame-Options: SAMEORIGIN
    Server: cloudflare

    {"result":[{"id":"b4b6f2**d5e1053ebac5106**ed32ace","type":"AAAA","name":"glamdring.dogspa.netconsonance.com","content":"2601:646:8080:f492:cec:602a:56a6:d43e","proxiable":true,"proxied":false,"ttl":1,"locked":false,"zone_id":"aa**dfa1218ae29dbdfe5fa**69cb682","zone_name":"netconsonance.com","modified_on":"2020-01-13T05:24:30.488051Z","created_on":"2020-01-13T05:24:30.488051Z","meta":{"auto_added":false,"managed_by_apps":false,"managed_by_argo_tunnel":false}}],"result_info":{"page":1,"per_page":20,"total_pages":1,"count":1,"total_count":1},"success":true,"errors":[],"messages":[]}ance.com","status":"pending","paused":false,"type":"full","development_mode":0,"name_servers":["beau.ns.cloudflare.com","colette.ns.cloudflare.com"],"original_name_servers":["ns-cloud-a1.googledomains.com","ns-cloud-a2.googledomains.com","ns-cloud-a3.googledomains.com","ns-cloud-a4.googledomains.com"],"original_registrar":"google llc (id: 895)","original_dnshost":null,"modified_on":"2020-01-13T05:24:30.488051Z","created_on":"2020-01-11T11:25:38.525131Z","activated_on":null,"meta":{"step":2,"wildcard_proxiable":false,"custom_certificate_quota":0,"page_rule_quota":3,"phishing_detected":false,"multiple_railguns_allowed":false},"owner":{"id":"409a04f8fc53f28091ce9f33a306ca7d","type":"user","email":"jrhett@netconsonance.com"},"account":{"id":"78cc6d0120b89d66f65d5ee57914243c","name":"jrhett@netconsonance.com"},"permissions":["#access:edit","#access:read","#analytics:read","#app:edit","#auditlogs:read","#billing:edit","#billing:read","#cache_purge:edit","#dns_records:edit","#dns_records:read","#lb:edit","#lb:read","#legal:edit","#legal:read","#logs:edit","#logs:read","#member:edit","#member:read","#organization:edit","#organization:read","#ssl:edit","#ssl:read","#stream:edit","#stream:read","#subscription:edit","#subscription:read","#waf:edit","#waf:read","#webhooks:edit","#webhooks:read","#worker:edit","#worker:read","#zone:edit","#zone:read","#zone_settings:edit","#zone_settings:read"],"plan":{"id":"0feeeeeeeeeeeeeeeeeeeeeeeeeeeeee","name":"Free Website","price":0,"currency":"USD","frequency":"","is_subscribed":true,"can_subscribe":false,"legacy_id":"free","legacy_discount":false,"externally_managed":false}}],"result_info":{"page":1,"per_page":20,"total_pages":1,"count":1,"total_count":1},"success":true,"errors":[],"messages":[]}
Jan 12 21:54:53  inadyn[60330] <Debug>: Successfully received HTTPS response (1321 bytes)!

If you look carefully you'll see that the JSON reply closes, but after the brace comes content from the first query. The function being called is here, but it would appear to be allocating and freeing the memory properly AFAICT https://github.com/troglobit/inadyn/blob/master/plugins/cloudflare.c#L199-L251

[jorhett]

@SimonPilkington you should be aware of this, since it might require changes to buffer use in get_id()

[SimonPilkington]

I'm confused as to what goes wrong here. It appears as though the response does not get null-terminated during the second request causing the buffer overrun, but http_transaction should null-terminate it.

I can't reproduce this behaviour locally. Can you explain how it happens?

[troglobit]

@SimonPilkington Might have been fixed by #292 ... I think. BUFSIZ on macOS seems to only be 1 kiB

[SimonPilkington]

That does not explain what goes wrong in the Cloudflare setup func where those requests are made. The response buffer there is an ad-hoc malloc of 4KiB independent of BUFSIZ. The response as shown in the output above is not enough to overflow it.

[troglobit]

You're right, maybe it could be a signal? Perhaps adding some logit() in CHECK() to see what errno is, in case of non-zero return value.

[SimonPilkington]

CHECK() would have bailed if there was a non-zero return value, but it doesn't look like that happened in the output.

@jorhett, since you're the only one who can reproduce this, can you investigate further, please? It could be a pretty serious problem. The second response should absolutely be null-terminated.

[jorhett]

I can't reproduce this behaviour locally. Can you explain how it happens?

As shown in the debug above, it appears during the two calls to get_id() (linked above) made by setup(), and appears (inconsistently) for the 2nd connection when retrieving the hostname id -- which has a significantly smaller response.

You're right, maybe it could be a signal? Perhaps adding some logit() in CHECK() to see what errno is, in case of non-zero return value.

Yeah I already went down that road added logs for the return code to check the buffer sizes returned. The debug isn't the best labeled, but this is showing pretty much every variable assignment inside get_id(). This debug starts immediately after the malloc:

   char *response_buf = malloc(RESP_BUFFER_SIZE * sizeof(char));

    if (!response_buf)
        return RC_OUT_OF_MEMORY;
    logit(LOG_DEBUG, "buffer: %i = %i\n%s\n", &response_buf, strlen(response_buf), response_buf);

    CHECK(http_construct(&client));

    http_set_port(&client, info->server_name.port);
    http_set_remote_name(&client, info->server_name.name);

    client.ssl_enabled = info->ssl_enabled;
    CHECK(http_init(&client, "Id query"));

    trans.req = request;
    trans.req_len = request_len;
    trans.rsp = response_buf;
    logit(LOG_DEBUG, "trans: %i\n", &trans);
    logit(LOG_DEBUG, "trans.rsp: %i\n", &trans.rsp);
    logit(LOG_DEBUG, "response_buf: %i\n", &response_buf);

And here's the output during one of the incidents:

Jan 12 23:06:37  inadyn[69212] <Debug>: buffer: -435979048 = 2558
    HTTP/1.1 200 OK
    Date: Mon, 13 Jan 2020 07:06:37 GMT
        ...snip previous response content...

Jan 12 23:06:37  inadyn[69212] <Info>: Id query, initiating HTTPS ...
Jan 12 23:06:37  inadyn[69212] <Info>: Id query, connecting to api.cloudflare.com([2606:4700:300a::6813:c01d]:443)
Jan 12 23:06:37  inadyn[69212] <Debug>: Certificate OK
Jan 12 23:06:37  inadyn[69212] <Info>: SSL server cert subject: C=US,ST=CA,L=San Francisco,O=CloudFlare\, Inc.,CN=api.cloudflare.com
Jan 12 23:06:37  inadyn[69212] <Info>: SSL server cert issuer: C=US,ST=CA,L=San Francisco,O=CloudFlare\, Inc.,CN=CloudFlare Inc ECC CA-2
Jan 12 23:06:37  inadyn[69212] <Debug>: trans: -435979040
Jan 12 23:06:37  inadyn[69212] <Debug>: trans.rsp: -435979024
Jan 12 23:06:37  inadyn[69212] <Debug>: response_buf: -435979048
Jan 12 23:06:37  inadyn[69212] <Debug>: Request:
    GET /client/v4/zones/aad8dfa1218ae29dbdfe5fa9569cb682/dns_records?type=AAAA&name=glamdring.dogspa.netconsonance.com HTTP/1.0
    Host: api.cloudflare.com
        ...snip...

Jan 12 23:06:37  inadyn[69212] <Debug>: Successfully sent HTTPS request!
Jan 12 23:06:37  inadyn[69212] <Info>: called: ret=4095 buf_len=4095 recv_len=-435979016
Jan 12 23:06:37  inadyn[69212] <Info>: reth: -28 Resource temporarily unavailable, try again.
Jan 12 23:06:37  inadyn[69212] <Info>: lenh: 4095
Jan 12 23:06:37  inadyn[69212] <Info>: reth: 1321 (unknown error code)
Jan 12 23:06:37  inadyn[69212] <Info>: lenh: 4095
Jan 12 23:06:37  inadyn[69212] <Info>: body len: 1321 buf_len: 2774 buf_size: 2558
Jan 12 23:06:37  inadyn[69212] <Info>: retb: -110 The TLS connection was non-properly terminated.
Jan 12 23:06:37  inadyn[69212] <Info>: body = 2558: HTTP/1.1 200 OK
    Date: Mon, 13 Jan 2020 07:06:37 GMT
    Content-Type: application/json
    Connection: close
        ...snip 2558 long string where only the first 1321 bytes are valid...

Jan 12 23:06:37  inadyn[69212] <Debug>: Successfully received HTTPS response (1321 bytes)!

There's no error being returned here other than not-ready, the positive result was the number of bytes returned. The code which calls http_connection does look right -- the buffer does get freed at the end of the block. It seems to be a memory allocation issue where you might get the same block.

I can force it not to happen by running a program that's doing lots of memory allocations at the same time. When my macbook was doing Time Machine backup for instance, I couldn't recreate it at all. As soon as it finished I could.

The second response should absolutely be null-terminated.

There isn't any code that adds a null termination. Neither the first nor the second is null-terminated, which is why IMHO this should be fixed in ssl_recv and http_recv

[SimonPilkington]

I'm still confused. https://github.com/troglobit/inadyn/blob/master/src/http.c#L138 should null-terminate the response, shouldn't it?

[jorhett]

Okay, here's the answer. I've cut out most of the text from that debug example. At the beginning of the routine we output the memory locations used by the various pieces (as shown above).

First call (for domain id):

Jan 12 23:42:21  inadyn[69789] <Debug>: buffer: -275055400 = 0
Jan 12 23:42:21  inadyn[69789] <Info>: Id query, initiating HTTPS ...
Jan 12 23:42:21  inadyn[69789] <Info>: Id query, connecting to api.cloudflare.com([2606:4700:300a::6813:c01d]:443)
Jan 12 23:42:21  inadyn[69789] <Debug>: Certificate OK
Jan 12 23:42:21  inadyn[69789] <Info>: SSL server cert subject: C=US,ST=CA,L=San Francisco,O=CloudFlare\, Inc.,CN=api.cloudflare.com
Jan 12 23:42:21  inadyn[69789] <Info>: SSL server cert issuer: C=US,ST=CA,L=San Francisco,O=CloudFlare\, Inc.,CN=CloudFlare Inc ECC CA-2
Jan 12 23:42:21  inadyn[69789] <Debug>: trans: -275055392
Jan 12 23:42:21  inadyn[69789] <Debug>: trans.rsp: -275055376
Jan 12 23:42:21  inadyn[69789] <Debug>: response_buf: -275055400
Jan 12 23:42:21  inadyn[69789] <Debug>: Request:
    GET /client/v4/zones?name=netconsonance.com HTTP/1.0

Second call (for hostname id):

Jan 12 23:42:21  inadyn[69789] <Debug>: Cloudflare Zone: 'netconsonance.com' Id: aad8dfa1218ae29dbdfe5fa9569cb682
Jan 12 23:42:21  inadyn[69789] <Debug>: buffer: -275055400 = 0
Jan 12 23:42:21  inadyn[69789] <Info>: Id query, initiating HTTPS ...
Jan 12 23:42:21  inadyn[69789] <Info>: Id query, connecting to api.cloudflare.com([2606:4700:300a::6813:c01d]:443)
Jan 12 23:42:21  inadyn[69789] <Debug>: Certificate OK
Jan 12 23:42:21  inadyn[69789] <Info>: SSL server cert subject: C=US,ST=CA,L=San Francisco,O=CloudFlare\, Inc.,CN=api.cloudflare.com
Jan 12 23:42:21  inadyn[69789] <Info>: SSL server cert issuer: C=US,ST=CA,L=San Francisco,O=CloudFlare\, Inc.,CN=CloudFlare Inc ECC CA-2
Jan 12 23:42:21  inadyn[69789] <Debug>: trans: -275055392
Jan 12 23:42:21  inadyn[69789] <Debug>: trans.rsp: -275055376
Jan 12 23:42:21  inadyn[69789] <Debug>: response_buf: -275055400
Jan 12 23:42:21  inadyn[69789] <Debug>: Request:
    GET /client/v4/zones/aad8dfa1218ae29dbdfe5fa9569cb682/dns_records?type=AAAA&name=glamdring.dogspa.netconsonance.com HTTP/1.0

If you look, the memory locations are all the same. This means that in addition to the buffer being full, the response length is already set to the original response length. So it's going to write the null at the end of the first/longer string.

AFAICT in the code you're the only one looking through http_connect twice, so I really can't tell if there's a problem in your code or if the function itself is unsafe--because nobody else would hit it.

But there's no point in having me work on this error, as it's been almost 30 years since I was chasing C-memory allocation problems and frankly, all it does is make me think it's dumb to be using C-lang for this. Or at least we should wrap all this so that plugin developers don't have to be C-lang devs.

[jorhett]

Perhaps just use memset to clear it out? Add this around line 124 -- just before calling http_connect ?

trans.rsp_len = 0;   /* length at 0 to start */
memset(response_buf, 0, sizeof(response_buf));  /* clear buffer memory */

@troglobit I'm really not a C memory person any more. I'm finding this really tedious. Your insight would be deeply appreciated.

[troglobit]

Not really sure I have much to add. But I can do some refactoring/cleanup of the code to see if we shake something out. It'll be all over the place unfortunately.

[troglobit]

OK, I've done some cleanup and improved a few checks. Hopefully I didn't mess up any of the logic. (Four new commits on master)

[jorhett]

@troglobit it has broken Cloudflare at least. We're losing one character from the ID being returned. Check this out:

Jan 13 23:54:32  inadyn[59490] <Debug>: Response:
    {"result":[{"id":"aad8dfa1218ae29dbdfe5fa9569cb682","name":"netconsonance.com", ...snip...
Jan 13 23:54:32  inadyn[59490] <Debug>: Cloudflare Zone: 'netconsonance.com' Id: aad8dfa1218ae29dbdfe5fa9569cb68
Jan 13 23:54:32  inadyn[59490] <Info>: Id query, initiating HTTPS ...

The final character from the id field is getting dropped. I think the bug is in calculating the length of the JSON value, it's using a difference rather than an inclusive number of characters: https://github.com/troglobit/inadyn/blob/master/plugins/cloudflare.c#L201

See #294 for debug output where you can see the problem. You probably don't want to merge all that debug, just sharing how I validated the problem.

[jorhett]

FYI you really should provide easy JSON value extraction functions in the main program. It's insane to be doing this kind of detail work in a plugin :(

[troglobit]

@jorhett Thanks for testing, I'll fix the off-by-one, but it indicates we might have been off with strncpy() since it acts as memcpy() if the source string doesn't have a NUL byte before it reaches max length. So that could explain a few things.

Fwiw, I agree that the JSON extraction stuff should be a part of the main Inadyn, but the JSON stuff is relatively new and not something I planned for back when, nor is the extremely complicated plugins we see now. We can refactor this later, let's focus on getting it to work rn.

[troglobit]

PR #294 merged.

[troglobit]

Hi guys, I'm trying to pick up the pieces here in an attempt to get a release out the door. Is this bug still an issue or can we close it?

[SimonPilkington]

I was never able to reproduce this issue, but looking at it now, it is definitely an issue, and my fault for forgetting that malloc doesn't zero the returned block. I believe calloc resolves things, but @jorhett should confirm since he is the one who found this issue to begin with.

For my part, the plugin appears functional.

[troglobit]

@SimonPilkington thanks for the quick follow-up! I'm updating documentation and closing issues right now, will probably release tomorrow afternoon, CET.

@jorhett I'd really appreciate your feedback, if you have the time.

[jorhett]

I don't have time this weekend to test. Like I said, it's not a visible bug unless you're reading debug output for another reason.

[troglobit]

@jorhett completely understand, thank you for taking the time to respond!

[troglobit]

So, v2.6 has been released https://github.com/troglobit/inadyn/releases/tag/v2.6, there are pre-built packages available, both Debian/Ubuntu packages and Docker images. Hopefully enough to help test this bug.