Two Missing P's

Arrgghh!!! I hate it when I outsmart myself!! I just finished a three-hour ordeal debugging why my app couldn't connect to my server.

I started by running the raw REST calls through Paw to make sure I was actually calling the REST endpoint correctly and I could create records on the backend.

Since this is an authenticated service I had to first sign-in, so I had to set up a separate configuration for that to get the user's token.

Next I setup the actual call to post the record, putting the user's email and their token in the header and the data for the record I wanted to create into the body (as JSON).

I ran it and everything worked fine. So it should have been as simple as do the same thing in the app. Riiiiiigggghhht.

In the app I'm using AlamoFire to make the REST calls and after successfully logging in I went on to (attempt) to create the new record.

This is what I got in the rails console:

User Load (2.1ms)  SELECT  "users".* FROM "users" WHERE "users"."email" = $1 ORDER BY "users"."id" ASC LIMIT $2  [["email", "test@home.com"], ["LIMIT", 1]]
Completed 400 Bad Request in 19ms (ActiveRecord: 2.1ms)

ActionController::ParameterMissing (param is missing or the value is empty: portfolio):

I know the load of the user is just Devise's before_action kicking in. But why don't I see even the parameters being passed in?

Ok, I thought, I have seen the param missing error before and it means for some reason my payload isn't getting to the server.

So I put in a few debug statements on the Rails side, specifically:

logger.debug "raw post: #{request.raw_post}"
logger.debug "params: #{params.as_json}"
logger.debug "local_params: #{portfolio_params.as_json}"

Note: portfolio_params is my "white list" method for the controller. This resulted in the following output:

User Load (2.5ms)  SELECT  "users".* FROM "users" WHERE "users"."email" = $1 ORDER BY "users"."id" ASC LIMIT $2  [["email", "test@home.com"], ["LIMIT", 1]]
raw post: {"portfolio":{"store_on_server":false, ... }}
params: {"controller"=>"api/v1/portfolios", "action"=>"create", "format"=>"json", "user_email"=>"test@home.com", "user_token"=>"_Csa8xXWzV-sfcazxdwJ"}
Completed 400 Bad Request in 11ms (ActiveRecord: 2.5ms)

Huh? Line 2 confirms my portfolio body is getting to the server, but when I look at the params on line 3, it's no where to be found.

Hmm, so I Google'd how to set the body in Swift 3 using AlamoFire and I found this post:

How to set body on post with AlamoFire

I looked at the example's syntax:

Alamofire.request("http://myserver.com", method: .post, parameters: parameters, encoding: JSONEncoding.default)
    .responseJSON { response in
        print(response)
    }

Here is what I had:

let request = Alamofire.request(urlString, method: .post, parameters: json, encoding: JSONEncoding.default, headers: headerCacheManager.getLatestHeaderFields())

Uhh, mine is the same EXCEPT for the call to add the header fields, but what could be wrong there? Surely the idiot programmer (me), who wrote the getLatestHeaderFields() method didn't mess that up right? I mean I have been successfully using that for months. So no need to check that right!?

Next I printed out the actual JSON on the app side, prior to passing it to AlamoFire:

print("JSON is: \(json.debugDescription)")

It looked right to me. Now what?

So I went old school. First I got the curl representation of what was working from Paw:

curl -X "POST" "http://localhost:3000/api/v1/portfolios" \
     -H "X-User-Token: _Csa8xXWzV-sfcazxdwJ" \
     -H "X-User-Email: test@home.com" \
     -H "Cookie: _pr_session=Uk1vVFUxSmRIS3J2YVN6UUlTRUczbzg4KytIbC9rajdXKzZTUDFiZ0laTnRzaTdCdERDYUFscmE0a05Zd3Y0eGdBV0lYKzNiWFIwOVpjM0Z0c3dpeWVwaWpsZWM2N1Nkb2xWZWRsM2VFazVybDhBd1Jaa2d1OHhQS2ZnQm1pbmo2bzZGTXBSSEh5Y3FtWkZZRnNnUzZFYmVTamVKTTVUUUNHaDFHOTdwb0h3VVNWWVBiS3ptNUlQUHI2Mk9iZXE1aTdnQi9aWk5HbnpzV3dlRXAyNzdFczVrckt5NEwzMk02QmRYSWxyS2IwbndzRFNXNDVsSzdYQlNVd0o4TUd3aC0tQVN0YkV2MWtXTGJyYVl3S0IxaHNLUT09--32ceac68ff051bf41d3437ecdc6b04730c00cc9d" \
     -H "Content-Type: application/json" \
     -H "Accept: application/json" \
     -d $'{
  "name": "Portfolio",
  "uuid": "uuid1"
}'

Pasting this into the console worked fine as well. But how could I see the request as it left the client? That's what I needed.

Eventually I figured out I could print a debug description of the AlamoFire request object which would give me the 'curl' command the app was using.

print("Request: \(request.debugDescription)")

The output of that was:

Request: $ curl -v \
    -X POST \
    -H "Content-Type: aaplication/json" \
    -H "X-User-Token: _Csa8xXWzV-sfcazxdwJ" \
    -H "Accept: aaplication/json" \
    -H "User-Agent: PortfolioRebalancer/1.0 (com.talonstrikesoftware.PortfolioRebalancer; build:1; iOS 10.3.1) Alamofire/4.5.0" \
    -H "Accept-Language: en;q=1.0" \
    -H "X-User-Email: test@home.com" \
    -H "Accept-Encoding: gzip;q=1.0, compress;q=0.5" \
    -d "{\"portfolio\":{\"store_on_server\":false, ...}" \
    "http://localhost:3000/api/v1/portfolios.json"

Do you see the problem? I didn't so I copied this string into a terminal window, executed it, and it failed.

Ok on to comparing each parameter. Do you see the problem now? Yeah, whether it was because it was late, or my monitor font was too small, or the fact I wrote this code months ago, it took me forever to see the problem.

It turns out about a week ago I had refactored the HeaderCacheManager class and I made a typo. What should have been:

headers["Accept"] = "application/json"
headers["Content-Type"] = "application/json"

was actually:

headers["Accept"] = "aaplication/json"
headers["Content-Type"] = "aaplication/json"

I misspelled the word application Doh!!!

Fixing those two p's the server responded like I would have expected:

Started POST "/api/v1/portfolios.json" for 172.17.0.1 at 2017-07-20 21:43:20 +0000
Processing by Api::V1::PortfoliosController#create as JSON
  Parameters: {"portfolio"=>{"store_on_server"=>false, ...}}
  User Load (2.9ms)  SELECT  "users".* FROM "users" WHERE "users"."email" = $1 ORDER BY "users"."id" ASC LIMIT $2  [["email", "test@home.com"], ["LIMIT", 1]]
  Portfolio Load (2.2ms)  SELECT  "portfolios".* FROM "portfolios" WHERE "portfolios"."uuid" = $1 ORDER BY "portfolios"."id" ASC LIMIT $2  [["uuid", "43E48CC3-286E-4CB2-914E-EBEA69707480"], ["LIMIT", 1]]
   (0.3ms)  BEGIN
  User Load (1.9ms)  SELECT  "users".* FROM "users" WHERE "users"."id" = $1 LIMIT $2  [["id", 1], ["LIMIT", 1]]
  SQL (1.8ms)  INSERT INTO "portfolios" [blah, blah ,blah]
   (0.5ms)  COMMIT
Completed 201 Created in 36ms (Views: 0.6ms | ActiveRecord: 9.6ms)

Done!!! In the end that request.debugDescription saved my bacon and I guess I just need to learn to spell better (or type better I'm not sure)

Till next time.