403 Forbidden error when uploading ID/ED-3D data to server

[martinburchell]

User reported problem uploading data to the server. By switching to multi-step mode, tracked down to the ID/ED-3D task (interleaved log files from client, Apache and server). Note the last request does not reach Apache:

Request 1

2023-10-30 14:05:17.595: Checking device is registered with server
2023-10-30 14:05:17.596: ... sending 156 bytes
2023-10-30 14:05:17.771: ... received 99 bytes
2023-10-30 14:05:17.771: ... OK

camcops.example.org:443 10.106.165.229 - - [30/Oct/2023:14:05:17 +0000] "POST /api HTTP/1.1" 200 6848 "-" "Mozilla/5.0"

2023-10-30 14:05:17.744 [p7027.t139665101989696] camcops_server.cc_modules.cc_tabletsession:INFO: Incoming client API connection from IP=78.145.192.75, port=None, device_name='{33682cea-6094-40cf-9a10-b2906103b221}', camcops_version=2.4.17, username=myuser, operation=check_device_registered

Request 2

2023-10-30 14:05:17.772: Checking user/device permitted to upload
2023-10-30 14:05:17.772: ... sending 223 bytes
2023-10-30 14:05:17.847: ... received 104 bytes
2023-10-30 14:05:17.847: ... OK

camcops.example.org:443 10.106.165.229 - - [30/Oct/2023:14:05:17 +0000] "POST /api HTTP/1.1" 200 668 "-" "Mozilla/5.0"

2023-10-30 14:05:17.831 [p7027.t139665101989696] camcops_server.cc_modules.cc_tabletsession:INFO: Incoming client API connection from IP=78.145.192.75, port=None, device_name='{33682cea-6094-40cf-9a10-b2906103b221}', camcops_version=2.4.17, username=myuser, operation=check_upload_user_and_device

Request 3

2023-10-30 14:05:17.847: Fetching server's version/ID policies/ID descriptions
2023-10-30 14:05:17.848: ... sending 206 bytes
2023-10-30 14:05:17.895: ... received 1.0 kilobytes
2023-10-30 14:05:17.896: ... OK

camcops.example.org:443 10.106.165.229 - - [30/Oct/2023:14:05:17 +0000] "POST /api HTTP/1.1" 200 994 "-" "Mozilla/5.0"

2023-10-30 14:05:17.878 [p7027.t139665101989696] camcops_server.cc_modules.cc_tabletsession:INFO: Incoming client API connection from IP=78.145.192.75, port=None, device_name='{33682cea-6094-40cf-9a10-b2906103b221}', camcops_version=2.4.17, username=myuser, operation=get_id_info

Request 4

2023-10-30 14:05:17.905: Validating patients for upload
2023-10-30 14:05:17.906: ... sending 492 bytes
2023-10-30 14:05:17.955: ... received 83 bytes
2023-10-30 14:05:17.956: ... OK

camcops.example.org:443 10.106.165.229 - - [30/Oct/2023:14:05:17 +0000] "POST /api HTTP/1.1" 200 642 "-" "Mozilla/5.0"

2023-10-30 14:05:17.940 [p7034.t139665101989696] camcops_server.cc_modules.cc_tabletsession:INFO: Incoming client API connection from IP=78.145.192.75, port=None, device_name='{33682cea-6094-40cf-9a10-b2906103b221}', camcops_version=2.4.17, username=myuser, operation=validate_patients

Request 5

2023-10-30 14:05:17.956: Fetching server's allowed tables/client versions
2023-10-30 14:05:17.956: ... sending 213 bytes
2023-10-30 14:05:18.056: ... received 4.5 kilobytes
2023-10-30 14:05:18.058: ... OK

camcops.example.org:443 10.106.165.229 - - [30/Oct/2023:14:05:18 +0000] "POST /api HTTP/1.1" 200 1869 "-" "Mozilla/5.0"

2023-10-30 14:05:18.031 [p7031.t139665101989696] camcops_server.cc_modules.cc_tabletsession:INFO: Incoming client API connection from IP=78.145.192.75, port=None, device_name='{33682cea-6094-40cf-9a10-b2906103b221}', camcops_version=2.4.17, username=myuser, operation=get_allowed_tables

Request 6

2023-10-30 14:05:18.205: Starting upload
2023-10-30 14:05:18.205: ... sending 207 bytes
2023-10-30 14:05:18.294: ... received 88 bytes
2023-10-30 14:05:18.294: ... OK

camcops.example.org:443 10.106.165.229 - - [30/Oct/2023:14:05:18 +0000] "POST /api HTTP/1.1" 200 651 "-" "Mozilla/5.0"

2023-10-30 14:05:18.238 [p7033.t139665101989696] camcops_server.cc_modules.cc_tabletsession:INFO: Incoming client API connection from IP=78.145.192.75, port=None, device_name='{33682cea-6094-40cf-9a10-b2906103b221}', camcops_version=2.4.17, username=myuser, operation=start_upload

Request 7

2023-10-30 14:05:18.295: Starting preservation
2023-10-30 14:05:18.295: ... sending 213 bytes
2023-10-30 14:05:18.355: ... received 93 bytes
2023-10-30 14:05:18.355: ... OK

camcops.example.org:443 10.106.165.229 - - [30/Oct/2023:14:05:18 +0000] "POST /api HTTP/1.1" 200 657 "-" "Mozilla/5.0"

2023-10-30 14:05:18.326 [p7030.t139665101989696] camcops_server.cc_modules.cc_tabletsession:INFO: Incoming client API connection from IP=78.145.192.75, port=None, device_name='{33682cea-6094-40cf-9a10-b2906103b221}', camcops_version=2.4.17, username=myuser, operation=start_preservation
2023-10-30 14:05:18.336 [p7030.t139665101989696] camcops_server.cc_modules.client_api:INFO: start_preservation successful

Request 8

2023-10-30 14:05:18.355: Uploading empty tables: ace3, aims, apeq_cpft_perinatal, apeqpt, asdas, audit, audit_c, badls, basdai, bdi, blobs, bmi, bprs, bprse, cage, cape42, caps, cardinal_expdet, cardinal_expdet_trialgroupspec, cardinal_expdet_trials, cardinal_expdetthreshold, cardinal_expdetthreshold_trials, cbir, cecaq3, cesd, cesdr, cgi, cgi_i, cgisch, cisr, ciwa, contactlog, cope_brief, core10, cpft_covid_medical, cpft_lps_discharge, cpft_lps_referral, cpft_lps_resetresponseclock, cpft_research_preferences, dad, das28, dast, deakin_1_healthreview, demoquestionnaire, demqol, demqolproxy, diagnosis_icd9cm, diagnosis_icd9cm_item, distressthermometer, elixhauserci, epds, esspri, factg, fast, fft, frs, gaf, gbogpc, gbogras, gbogres, gds15, gmcpq, hads, hads_respondent, hama, hamd, hamd7, honos, honos65, honosca, icd10depressive, icd10manic, icd10mixed, icd10schizophrenia, icd10schizotypal, icd10specpd, iesr, ifs, irac, khandaker_1_medicalhistory, khandaker_mojo_medical, khandaker_mojo_medication_item, khandaker_mojo_medicationtherapy, khandaker_mojo_sociodemographics, khandaker_mojo_therapy_item, lynall_1_iam_medical, lynall_iam_life, maas, mast, mds_updrs, mfi20, miniace, moca, nart, npiq, ors, panss, paradise24, pbq, pcl5, pclc, pclm, pcls, pdss, perinatal_poem, photo, photosequence, photosequence_photos, phq15, phq8, progressnote, pswq, psychiatricclerking, pt_satis, qolbasic, qolsg, rand36, rapid3, ref_satis_gen, ref_satis_spec, sfmpq2, shaps, slums, smast, srs, swemwbs, wemwbs, wsas, ybocs, ybocssc, zbi12
2023-10-30 14:05:18.356: ... sending 1.8 kilobytes
2023-10-30 14:05:18.665: ... received 95 bytes
2023-10-30 14:05:18.665: ... OK

camcops.example.org:443 10.106.165.229 - - [30/Oct/2023:14:05:18 +0000] "POST /api HTTP/1.1" 200 659 "-" "Mozilla/5.0"

2023-10-30 14:05:18.390 [p7030.t139665101989696] camcops_server.cc_modules.cc_tabletsession:INFO: Incoming client API connection from IP=78.145.192.75, port=None, device_name='{33682cea-6094-40cf-9a10-b2906103b221}', camcops_version=2.4.17, username=myuser, operation=upload_empty_tables
2023-10-30 14:05:18.579 [p7030.t139665101989696] camcops_server.cc_modules.client_api:INFO: upload_empty_tables

Request 9

2023-10-30 14:05:18.665: Uploading table: chit
2023-10-30 14:05:18.666: ... sending 711 bytes
2023-10-30 14:05:18.745: ... received 104 bytes
2023-10-30 14:05:18.745: ... OK

camcops.example.org:443 10.106.165.229 - - [30/Oct/2023:14:05:18 +0000] "POST /api HTTP/1.1" 200 663 "-" "Mozilla/5.0"

2023-10-30 14:05:18.713 [p7025.t139665101989696] camcops_server.cc_modules.cc_tabletsession:INFO: Incoming client API connection from IP=78.145.192.75, port=None, device_name='{33682cea-6094-40cf-9a10-b2906103b221}', camcops_version=2.4.17, username=myuser, operation=upload_table
2023-10-30 14:05:18.730 [p7025.t139665101989696] camcops_server.cc_modules.client_api:INFO: Upload successful; 1 records uploaded to table chit (1 new, 0 modified, 0 identical, 0 deleted)

Request 10

2023-10-30 14:05:18.746: Uploading table: cia
2023-10-30 14:05:18.747: ... sending 720 bytes
2023-10-30 14:05:18.838: ... received 103 bytes
2023-10-30 14:05:18.838: ... OK

camcops.example.org:443 10.106.165.229 - - [30/Oct/2023:14:05:18 +0000] "POST /api HTTP/1.1" 200 662 "-" "Mozilla/5.0"

2023-10-30 14:05:18.810 [p7026.t139665101989696] camcops_server.cc_modules.cc_tabletsession:INFO: Incoming client API connection from IP=78.145.192.75, port=None, device_name='{33682cea-6094-40cf-9a10-b2906103b221}', camcops_version=2.4.17, username=myuser, operation=upload_table
2023-10-30 14:05:18.822 [p7026.t139665101989696] camcops_server.cc_modules.client_api:INFO: Upload successful; 1 records uploaded to table cia (1 new, 0 modified, 0 identical, 0 deleted)

Request 11

2023-10-30 14:05:18.838: Uploading table: diagnosis_icd10
2023-10-30 14:05:18.839: ... sending 858 bytes
2023-10-30 14:05:18.946: ... received 115 bytes
2023-10-30 14:05:18.946: ... OK

camcops.example.org:443 10.106.165.229 - - [30/Oct/2023:14:05:18 +0000] "POST /api HTTP/1.1" 200 674 "-" "Mozilla/5.0"

2023-10-30 14:05:18.918 [p7027.t139665101989696] camcops_server.cc_modules.cc_tabletsession:INFO: Incoming client API connection from IP=78.145.192.75, port=None, device_name='{33682cea-6094-40cf-9a10-b2906103b221}', camcops_version=2.4.17, username=myuser, operation=upload_table
2023-10-30 14:05:18.931 [p7027.t139665101989696] camcops_server.cc_modules.client_api:INFO: Upload successful; 1 records uploaded to table diagnosis_icd10 (1 new, 0 modified, 0 identical, 0 deleted)

Request 12

2023-10-30 14:05:18.947: Uploading table: diagnosis_icd10_item
2023-10-30 14:05:18.948: ... sending 586 bytes
2023-10-30 14:05:19.007: ... received 120 bytes
2023-10-30 14:05:19.008: ... OK

camcops.example.org:443 10.106.165.229 - - [30/Oct/2023:14:05:18 +0000] "POST /api HTTP/1.1" 200 679 "-" "Mozilla/5.0"

2023-10-30 14:05:18.983 [p7027.t139665101989696] camcops_server.cc_modules.cc_tabletsession:INFO: Incoming client API connection from IP=78.145.192.75, port=None, device_name='{33682cea-6094-40cf-9a10-b2906103b221}', camcops_version=2.4.17, username=myuser, operation=upload_table
2023-10-30 14:05:18.992 [p7027.t139665101989696] camcops_server.cc_modules.client_api:INFO: Upload successful; 1 records uploaded to table diagnosis_icd10_item (1 new, 0 modified, 0 identical, 0 deleted)

Request 13

2023-10-30 14:05:19.008: Uploading table: edeq
2023-10-30 14:05:19.009: ... sending 910 bytes
2023-10-30 14:05:19.074: ... received 104 bytes
2023-10-30 14:05:19.075: ... OK

camcops.example.org:443 10.106.165.229 - - [30/Oct/2023:14:05:19 +0000] "POST /api HTTP/1.1" 200 663 "-" "Mozilla/5.0"

2023-10-30 14:05:19.046 [p7022.t139665101989696] camcops_server.cc_modules.cc_tabletsession:INFO: Incoming client API connection from IP=78.145.192.75, port=None, device_name='{33682cea-6094-40cf-9a10-b2906103b221}', camcops_version=2.4.17, username=myuser, operation=upload_table
2023-10-30 14:05:19.057 [p7022.t139665101989696] camcops_server.cc_modules.client_api:INFO: Upload successful; 1 records uploaded to table edeq (1 new, 0 modified, 0 identical, 0 deleted)

Request 14

2023-10-30 14:05:19.075: Uploading table: eq5d5l
2023-10-30 14:05:19.077: ... sending 635 bytes
2023-10-30 14:05:19.183: ... received 106 bytes
2023-10-30 14:05:19.183: ... OK

camcops.example.org:443 10.106.165.229 - - [30/Oct/2023:14:05:19 +0000] "POST /api HTTP/1.1" 200 665 "-" "Mozilla/5.0"

2023-10-30 14:05:19.156 [p7034.t139665101989696] camcops_server.cc_modules.cc_tabletsession:INFO: Incoming client API connection from IP=78.145.192.75, port=None, device_name='{33682cea-6094-40cf-9a10-b2906103b221}', camcops_version=2.4.17, username=myuser, operation=upload_table
2023-10-30 14:05:19.167 [p7034.t139665101989696] camcops_server.cc_modules.client_api:INFO: Upload successful; 1 records uploaded to table eq5d5l (1 new, 0 modified, 0 identical, 0 deleted)

Request 15

2023-10-30 14:05:19.184: Uploading table: gad7
2023-10-30 14:05:19.185: ... sending 632 bytes
2023-10-30 14:05:19.247: ... received 104 bytes
2023-10-30 14:05:19.248: ... OK

camcops.example.org:443 10.106.165.229 - - [30/Oct/2023:14:05:19 +0000] "POST /api HTTP/1.1" 200 663 "-" "Mozilla/5.0"

2023-10-30 14:05:19.218 [p7020.t139665101989696] camcops_server.cc_modules.cc_tabletsession:INFO: Incoming client API connection from IP=78.145.192.75, port=None, device_name='{33682cea-6094-40cf-9a10-b2906103b221}', camcops_version=2.4.17, username=myuser, operation=upload_table
2023-10-30 14:05:19.230 [p7020.t139665101989696] camcops_server.cc_modules.client_api:INFO: Upload successful; 1 records uploaded to table gad7 (1 new, 0 modified, 0 identical, 0 deleted)

Request 16

2023-10-30 14:05:19.248: Uploading table: ided3d
2023-10-30 14:05:19.252: ... sending 2.2 kilobytes
2023-10-30 14:05:19.292: Network failure: Error transferring https://camcops.example.org:443/api - server replied: Forbidden

[martinburchell]

This turns out to be a problem with the Microsoft Azure Web Application Firewall sitting in front of CamCOPS and nothing to do with CamCOPS itself:

The original failing request:

curl -d "camcops_version=2.4.17&device=%7B33682cea-6094-40cf-9a10-b2906103b221%7D&fields=id%2C_move_off_tablet%2Cwhen_last_modified%2Cwhen_created%2Cfirstexit_is_finish%2Cfirstexit_is_abort%2Cwhen_firstexit%2Cediting_time_s%2Cpatient_id%2Clast_stage%2Cmax_trials_per_stage%2Cprogress_criterion_x%2Cprogress_criterion_y%2Cmin_number%2Cmax_number%2Cpause_after_beep_ms%2Citi_ms%2Ccounterbalance_dimensions%2Cvolume%2Coffer_abort%2Cdebug_display_stimuli_only%2Cshape_definitions_svg%2Ccolour_definitions_rgb%2Caborted%2Cfinished%2Clast_trial_completed&nrecords=1&operation=upload_table&password=mypasswordredacted&pkname=id&record0=1%2CNULL%2C%272023-10-24T15%3A10%3A55.106%2B01%3A00%27%2C%272023-10-24T15%3A07%3A33.625%2B01%3A00%27%2C1%2C0%2C%272023-10-24T15%3A07%3A44.704%2B01%3A00%27%2C201.443%2C1%2C8%2C50%2C6%2C6%2C1%2C9%2C500%2C500%2C3%2C0.5%2C0%2C0%2C%27%5B%22m10%2C-53%20l20%2C100%20l-60%2C0%20z%20m50%2C60%20l-120%2C20%20l0%2C-50%20z%22%2C%22m0%2C-50%20l-57%2C57%20l28%2C28%20l28%2C-28%20l28%2C28%20l28%2C-28%20z%22%2C%22m-15%2C-50%20l-45%2C25%20l90%2C0%20z%20m15%2C35%20l-45%2C25%20l90%2C0%20z%20m15%2C35%20l-45%2C25%20l90%2C0%20z%22%2C%22m-60%2C-11%20l94%2C55%20l26%2C-28%20l-38%2C-15%20l38%2C-15%20l-26%2C-28%20l-94%2C55%20z%22%2C%22m-20%2C-50%20l-40%2C50%20l45%2C0%20l0%2C50%20l30%2C0%20l0%2C-50%20l45%2C0%20l-45%2C-50%20z%22%2C%22m-60%2C-36%20l120%2C0%20l0%2C72%20l-40%2C0%20l0%2C-36%20l-40%2C0%20l0%2C36%2C%20l-40%2C0%20z%22%2C%22m0%2C-40%20l60%2C40%20l-40%2C27%20l0%2C13%20l-40%2C0%20l0%2C-13%20l-40%2C-27%20z%22%2C%22m-33%2C40%20l-27%2C-40%20l27%2C-40%20l33%2C27%20l33%2C-27%20l27%2C40%20l-27%2C40%20l-33%2C-27%20z%22%2C%22m-60%2C-30%20l60%2C-30%20l60%2C30%20l0%2C60%20l-60%2C30%20l-60%2C-30%20z%22%2C%22m-60%2C60%20l120%2C0%20l-60%2C-60%20z%20m0%2C-120%20l120%2C0%20l-60%2C60%20z%22%2C%22m-60%2C-40%20l0%2C68%20l120%2C0%20l-45%2C-30%20l0%2C11%20l-45%2C-38%20l0%2C23%20z%22%2C%22m-60%2C0%20l34%2C-43%20l86%2C0%20l-34%2C43%20l34%2C43%20l-86%2C0%20z%22%5D%27%2C%27%5B%22%23555555%22%2C%22%235555ff%22%2C%22%2355ff55%22%2C%22%2355ffff%22%2C%22%23ff5555%22%2C%22%23ff55ff%22%2C%22%23ffff55%22%2C%22%23ffffff%22%5D%27%2C0%2C1%2C60&session_id=5562616&session_token=Jmm0YmRMeMf1KAJ_SZ3-PA%3D%3D&table=ided3d&user=myuser" -X POST https://camcops.example.org/api

This seems to be enough to trigger the 403:

curl -d "foo=%22%22" -X POST https://camcops.example.org/api`

This is a working request for a different task in so much as it gets through the firewall:

curl -d "camcops_version=2.4.17&device=%7B33682cea-6094-40cf-9a10-b2906103b221%7D&fields=id%2C_move_off_tablet%2Cwhen_last_modified%2Cwhen_created%2Cfirstexit_is_finish%2Cfirstexit_is_abort%2Cwhen_firstexit%2Cediting_time_s%2Cpatient_id%2Cq1%2Cq2%2Cq3%2Cq4%2Cq5%2Cq6%2Cq7&nrecords=1&operation=upload_table&password=mypasswordredacted&pkname=id&record0=1%2CNULL%2C%272023-10-24T15%3A00%3A54.547%2B01%3A00%27%2C%272023-10-24T15%3A00%3A45.862%2B01%3A00%27%2C1%2C0%2C%272023-10-24T15%3A00%3A54.546%2B01%3A00%27%2C8.661%2C1%2C0%2C0%2C0%2C0%2C0%2C0%2C" -X POST https://camcops.example.org/api`

Fixed by turning off the OWASP rule that was blocking %22 (the double quote character)

[martinburchell]

The OWASP rules in question in this case were 942110 and 942330 (SQL injection)