Some debugging/log-grabbing help sought.

[fadams]

Hello,
I'm trying to create a simple unzip function using hotwrap. The Dockerfile looks like:

FROM alpine:latest

# Install hotwrap binary
COPY --from=fnproject/hotwrap:latest /hotwrap /hotwrap 

# unzip - list, test and extract compressed files in a ZIP archive
# With Alpine we don't need to explicitly install anything as unzip is
# provided by busybox.
CMD /usr/bin/unzip -p -

# update entrypoint to use hotwrap, this will wrap the command 
ENTRYPOINT ["/hotwrap"]

and func.yaml looks like:

schema_version: 20180708
name: unzip-hotwrap
version: 0.0.1
runtime: docker
triggers:
- name: unzip-hotwrap
  type: http
  source: /unzip-hotwrap

To create the app and deploy the function:

fn create app archive
fn --verbose deploy --app archive

So far so good and the piped unzip appears to work running the alpine busybox unzip directly in the container via:

cat test.zip | docker run --rm -i --entrypoint=usr/bin/unzip docker-mint.local:5000/unzip-hotwrap:0.0.2 -p -

with my simple zipped text file test.zip the above command displays the unzipped text on stdout as I'd have expected/hoped.

However when I try to invoke the deployed function:

cat test.zip | fn invoke archive unzip-hotwrap

I see

error running exec: exit status 1

similarly if I use Curl

curl --data-binary test.zip http://10.192.0.2:30090/t/archive/unzip-hotwrap

TBH I'm not really sure the best way to go about figuring out what has gone wrong, I'h have guessed that the zip file is somehow not being sent as binary, though I am using --data-binary in the Curl call, though it's possible that hotwrap might be munging the binary, but TBH I've no clue how that works or to work out if that is indeed the case.

I came across this post https://medium.com/fnproject/sending-function-logs-to-papertrail-c1ba2bae62e6 that has some info on getting function logs, however when I do:

fn list calls archive unzip-hotwrap

I get

Fn: [GET /fns/{fnID}/calls][410] getFnsFnIdCallsGone 

See 'fn <command> --help' for more information. Client version: 0.5.69

so I'm wondering if something has changed in the way function logs are retrieved since that article was written?

I'd really appreciate any help suggesting what I might be doing wrong, even some pointers to help get some more useful info than just "error running exec: exit status 1".

MTIA

[rdallman]

hey @fadams - you may try fn start --log-level=debug / docker run -e "FN_LOG_LEVEL=debug" fnproject/fnserver to get logs from your function out, we're working on improving the out of the box logging experience (#1479). the fn calls and logs apis are removed. hopefully, with some logs, can start seeing what's going on, am not too sure about facilities for debugging hotwrap, personally.

[fadams]

Hi again @rdallman thanks for the tip. That has helped me to discover a little more, though I'd still appreciate some pointers.

What I have discovered so far.... well, as I mention in my original post I'm trying a fairly simple function based on this Dockerfile which is using hotwrap:

FROM alpine:latest

# Install hotwrap binary
COPY --from=fnproject/hotwrap:latest /hotwrap /hotwrap 

# unzip - list, test and extract compressed files in a ZIP archive
# With Alpine we don't need to explicitly install anything as unzip is
# provided by busybox.
CMD /usr/bin/unzip -p -

# update entrypoint to use hotwrap, this will wrap the command 
ENTRYPOINT ["/hotwrap"]

When I simply run the container's busybox unzip (where I have to unset the entrypoint 'cause it's using hotwrap) e.g. by doing:

cat test.zip | docker run --rm -i --entrypoint=/usr/bin/unzip docker-mint.local:5000/unzip-hotwrap:0.0.2 -p -

or

cat test.zip | docker run --rm -i --entrypoint="" docker-mint.local:5000/unzip-hotwrap:0.0.2 /usr/bin/unzip -p -

everything is happy an my simple text zip unzips to stdout, though none of it is using Fn at that point.

When I do

cat test.zip | fn invoke archive unzip-hotwrap

as I mention above it fails, but looking at the debug logs I'm seeing something interesting - they are pretty verbose so I've just included some of the key bits here - what I end up seeing is:

...
time="2019-05-09T14:27:37Z" level=debug msg="2019/05/09 14:27:37 /bin/sh -c /usr/bin/unzip -p -\n" action="server.handleFnInvokeCall)-fm" app_id=01DAEFT69XNG8G010ZJ0000001 call_id=01DAEFW387NG8G010ZJ0000004 fn_id=01DAEFTSDPNG8G010ZJ0000002 image="docker-mint.local:5000/unzip-hotwrap:0.0.2" user_log=true
time="2019-05-09T14:27:37Z" level=debug msg="BusyBox v1.29.3 (2019-01-24 07:45:07 UTC) multi-call binary.\n" action="server.handleFnInvokeCall)-fm" app_id=01DAEFT69XNG8G010ZJ0000001 call_id=01DAEFW387NG8G010ZJ0000004 fn_id=01DAEFTSDPNG8G010ZJ0000002 image="docker-mint.local:5000/unzip-hotwrap:0.0.2" user_log=true
time="2019-05-09T14:27:37Z" level=debug msg="\n" action="server.handleFnInvokeCall)-fm" app_id=01DAEFT69XNG8G010ZJ0000001 call_id=01DAEFW387NG8G010ZJ0000004 fn_id=01DAEFTSDPNG8G010ZJ0000002 image="docker-mint.local:5000/unzip-hotwrap:0.0.2" user_log=true
time="2019-05-09T14:27:37Z" level=debug msg="Usage: unzip [-lnojpq] FILE[.zip] [FILE]... [-x FILE...] [-d DIR]\n" action="server.handleFnInvokeCall)-fm" app_id=01DAEFT69XNG8G010ZJ0000001 call_id=01DAEFW387NG8G010ZJ0000004 fn_id=01DAEFTSDPNG8G010ZJ0000002 image="docker-mint.local:5000/unzip-hotwrap:0.0.2" user_log=true
time="2019-05-09T14:27:37Z" level=debug msg="\n" action="server.handleFnInvokeCall)-fm" app_id=01DAEFT69XNG8G010ZJ0000001 call_id=01DAEFW387NG8G010ZJ0000004 fn_id=01DAEFTSDPNG8G010ZJ0000002 image="docker-mint.local:5000/unzip-hotwrap:0.0.2" user_log=true
time="2019-05-09T14:27:37Z" level=debug msg="Extract FILEs from ZIP archive\n" action="server.handleFnInvokeCall)-fm" app_id=01DAEFT69XNG8G010ZJ0000001 call_id=01DAEFW387NG8G010ZJ0000004 fn_id=01DAEFTSDPNG8G010ZJ0000002 image="docker-mint.local:5000/unzip-hotwrap:0.0.2" user_log=true
time="2019-05-09T14:27:37Z" level=debug msg="\n" action="server.handleFnInvokeCall)-fm" app_id=01DAEFT69XNG8G010ZJ0000001 call_id=01DAEFW387NG8G010ZJ0000004 fn_id=01DAEFTSDPNG8G010ZJ0000002 image="docker-mint.local:5000/unzip-hotwrap:0.0.2" user_log=true
time="2019-05-09T14:27:37Z" level=debug msg="\t-l\tList contents (with -q for short form)\n" action="server.handleFnInvokeCall)-fm" app_id=01DAEFT69XNG8G010ZJ0000001 call_id=01DAEFW387NG8G010ZJ0000004 fn_id=01DAEFTSDPNG8G010ZJ0000002 image="docker-mint.local:5000/unzip-hotwrap:0.0.2" user_log=true
time="2019-05-09T14:27:37Z" level=debug msg="\t-n\tNever overwrite files (default: ask)\n" action="server.handleFnInvokeCall)-fm" app_id=01DAEFT69XNG8G010ZJ0000001 call_id=01DAEFW387NG8G010ZJ0000004 fn_id=01DAEFTSDPNG8G010ZJ0000002 image="docker-mint.local:5000/unzip-hotwrap:0.0.2" user_log=true
time="2019-05-09T14:27:37Z" level=debug msg="\t-o\tOverwrite\n" action="server.handleFnInvokeCall)-fm" app_id=01DAEFT69XNG8G010ZJ0000001 call_id=01DAEFW387NG8G010ZJ0000004 fn_id=01DAEFTSDPNG8G010ZJ0000002 image="docker-mint.local:5000/unzip-hotwrap:0.0.2" user_log=true
time="2019-05-09T14:27:37Z" level=debug msg="\t-j\tDo not restore paths\n" action="server.handleFnInvokeCall)-fm" app_id=01DAEFT69XNG8G010ZJ0000001 call_id=01DAEFW387NG8G010ZJ0000004 fn_id=01DAEFTSDPNG8G010ZJ0000002 image="docker-mint.local:5000/unzip-hotwrap:0.0.2" user_log=true
time="2019-05-09T14:27:37Z" level=debug msg="\t-p\tPrint to stdout\n" action="server.handleFnInvokeCall)-fm" app_id=01DAEFT69XNG8G010ZJ0000001 call_id=01DAEFW387NG8G010ZJ0000004 fn_id=01DAEFTSDPNG8G010ZJ0000002 image="docker-mint.local:5000/unzip-hotwrap:0.0.2" user_log=true
...

The main bit of interest in this is the bit:

/bin/sh -c /usr/bin/unzip -p -

Now bear in mind what my original Dockerfile looks like and also the previous docker run calls and not a /bin/sh -c to be seen. Now if I try a different docker run like this:

cat test.zip | docker run --rm -i --entrypoint="" docker-mint.local:5000/unzip-hotwrap:0.0.2 /bin/sh -c /usr/bin/unzip -p -

what I get is:

BusyBox v1.29.3 (2019-01-24 07:45:07 UTC) multi-call binary.

Usage: unzip [-lnojpq] FILE[.zip] [FILE]... [-x FILE...] [-d DIR]

Extract FILEs from ZIP archive

	-l	List contents (with -q for short form)
	-n	Never overwrite files (default: ask)
	-o	Overwrite
	-j	Do not restore paths
	-p	Print to stdout
	-q	Quiet
	-x FILE	Exclude FILEs
	-d DIR	Extract into DIR

i.e. the usage message which if you pore over the Fn debug logs seems to be what I'm getting when I try to invoke this.

So it looks like my problem is down to hotwrap calling my actual unzip executable via /bin/sh -c rather than directly which I suspect is then not passing stdin, which is where the hyphen in the /usr/bin/unzip -p - call fits in.

My shell foo isn't as hot as I might like so I'd really appreciate any suggestions as to how I might rewrite the CMD /usr/bin/unzip -p - bit of my Dockerfile so that it doesn't get borked by being called via /bin/sh -c

MTIA and thanks again for the logging help that identified what actually seems to be going on.

[fadams]

Okey Dokey. I've made some progress, after a bit of tinkering around it seems like putting quotes round the unzip call works, that is to say:

cat test.zip | docker run --rm -i --entrypoint="" docker-mint.local:5000/unzip-hotwrap:0.0.2 /bin/sh -c "/usr/bin/unzip -p -"

Then I though D'oh is my problem that I'm using the shell form of CMD as described here https://docs.docker.com/engine/reference/builder/ when I've also specified ENTRYPOINT (so the CMD should really be the ENTRYPOINT parameters). I think my issue is explained under the "Understand how CMD and ENTRYPOINT interact" section in the table my ENTRYPOINT was of the form [“exec_entry”, “p1_entry”] and my CMD was of the form CMD exec_cmd p1_cmd so from the matrix the executed command was of the form exec_entry p1_entry /bin/sh -c exec_cmd p1_cmd

I rewrote my Dockerfile to look like this:

FROM alpine:latest

# Install hotwrap binary
COPY --from=fnproject/hotwrap:latest /hotwrap /hotwrap 

# unzip - list, test and extract compressed files in a ZIP archive
# With Alpine we don't need to explicitly install anything as unzip is
# provided by busybox.
CMD ["/usr/bin/unzip -p -"]

# update entrypoint to use hotwrap, this will wrap the command 
ENTRYPOINT ["/hotwrap"]

and now

cat test.zip | fn invoke archive unzip-hotwrap

seems to be working and the debug logs say:

time="2019-05-09T17:10:57Z" level=debug msg="docker unpause" app_id=01DAEFT69XNG8G010ZJ0000001 call_id=01DAES6P7PNG8G010ZJ000000T container_id=01DAES6P7PNG8G010ZJ000000T cpus= fn_id=01DAEFTSDPNG8G010ZJ0000002 idle_timeout=30 image="docker-mint.local:5000/unzip-hotwrap:0.0.2" memory=128 stack=Unfreeze
time="2019-05-09T17:10:57Z" level=info msg="starting call" action="server.handleFnInvokeCall)-fm" app_id=01DAEFT69XNG8G010ZJ0000001 call_id=01DAES771MNG8G010ZJ000000W container_id=01DAES6P7PNG8G010ZJ000000T fn_id=01DAEFTSDPNG8G010ZJ0000002
time="2019-05-09T17:10:57Z" level=debug msg="2019/05/09 17:10:57 /usr/bin/unzip -p - \n" action="server.handleFnInvokeCall)-fm" app_id=01DAEFT69XNG8G010ZJ0000001 call_id=01DAES771MNG8G010ZJ000000W fn_id=01DAEFTSDPNG8G010ZJ0000002 image="docker-mint.local:5000/unzip-hotwrap:0.0.2" user_log=true
time="2019-05-09T17:10:57Z" level=debug msg="Got resp from UDS socket" action="server.handleFnInvokeCall)-fm" app_id=01DAEFT69XNG8G010ZJ0000001 call_id=01DAES771MNG8G010ZJ000000W fn_id=01DAEFTSDPNG8G010ZJ0000002 resp="&{200 OK 200 HTTP/1.1 1 1 map[Date:[Thu, 09 May 2019 17:10:57 GMT] Content-Type:[text/plain; charset=utf-8]] 0xc420199b20 -1 [chunked] false false map[] 0xc4205fd300 <nil>}"
time="2019-05-09T17:10:57Z" level=debug msg="docker pause" app_id=01DAEFT69XNG8G010ZJ0000001 call_id=01DAES6P7PNG8G010ZJ000000T container_id=01DAES6P7PNG8G010ZJ000000T cpus= fn_id=01DAEFTSDPNG8G010ZJ0000002 idle_timeout=30 image="docker-mint.local:5000/unzip-hotwrap:0.0.2" memory=128 stack=Freeze

So I'm no longer seeing the /bin/sh -c

One issue I'm still seeing though is an error when I try to invoke via Curl e.g.

curl --data-binary test.zip http://172.16.199.129:8080/t/archive/unzip-hotwrap

The logs say:

time="2019-05-09T17:15:11Z" level=debug msg="setting tmpfs" app_id=01DAEFT69XNG8G010ZJ0000001 call_id=01DAESEYXQNG8G010ZJ0000011 container_id=01DAESEYXQNG8G010ZJ0000011 cpus= fn_id=01DAEFTSDPNG8G010ZJ0000002 idle_timeout=30 image="docker-mint.local:5000/unzip-hotwrap:0.0.2" memory=128 options= stack=CreateCookie target=/tmp
time="2019-05-09T17:15:11Z" level=debug msg="setting bind" app_id=01DAEFT69XNG8G010ZJ0000001 bind="/home/fadams/Development/serverless/fn/server/iofs/iofs267697502:/tmp/iofs" call_id=01DAESEYXQNG8G010ZJ0000011 container_id=01DAESEYXQNG8G010ZJ0000011 cpus= fn_id=01DAEFTSDPNG8G010ZJ0000002 idle_timeout=30 image="docker-mint.local:5000/unzip-hotwrap:0.0.2" memory=128 stack=CreateCookie
time="2019-05-09T17:15:11Z" level=debug msg="setting hostname" app_id=01DAEFT69XNG8G010ZJ0000001 call_id=01DAESEYXQNG8G010ZJ0000011 container_id=01DAESEYXQNG8G010ZJ0000011 cpus= fn_id=01DAEFTSDPNG8G010ZJ0000002 hostname=d738648acd71 idle_timeout=30 image="docker-mint.local:5000/unzip-hotwrap:0.0.2" memory=128 stack=CreateCookie
time="2019-05-09T17:15:11Z" level=debug msg="setting security" CapDrop="[all]" SecurityOpt="[no-new-privileges:true]" app_id=01DAEFT69XNG8G010ZJ0000001 call_id=01DAESEYXQNG8G010ZJ0000011 container_id=01DAESEYXQNG8G010ZJ0000011 cpus= fn_id=01DAEFTSDPNG8G010ZJ0000002 idle_timeout=30 image="docker-mint.local:5000/unzip-hotwrap:0.0.2" memory=128 stack=CreateCookie user="1000:1000"
time="2019-05-09T17:15:11Z" level=debug msg="docker inspect image" app_id=01DAEFT69XNG8G010ZJ0000001 call_id=01DAESEYXQNG8G010ZJ0000011 container_id=01DAESEYXQNG8G010ZJ0000011 cpus= fn_id=01DAEFTSDPNG8G010ZJ0000002 idle_timeout=30 image="docker-mint.local:5000/unzip-hotwrap:0.0.2" memory=128 stack=ValidateImage
time="2019-05-09T17:15:11Z" level=debug msg="docker create container" app_id=01DAEFT69XNG8G010ZJ0000001 call_id=01DAESEYXQNG8G010ZJ0000011 container_id=01DAESEYXQNG8G010ZJ0000011 cpus= fn_id=01DAEFTSDPNG8G010ZJ0000002 idle_timeout=30 image="docker-mint.local:5000/unzip-hotwrap:0.0.2" memory=128 stack=CreateContainer
time="2019-05-09T17:15:12Z" level=debug msg="fsnotify event" app_id=01DAEFT69XNG8G010ZJ0000001 container_id=01DAESEYXQNG8G010ZJ0000011 cpus= event="\"/iofs/iofs267697502/phonylsnr.sock\": CREATE" fn_id=01DAEFTSDPNG8G010ZJ0000002 idle_timeout=30 image="docker-mint.local:5000/unzip-hotwrap:0.0.2" memory=128
time="2019-05-09T17:15:12Z" level=debug msg="fsnotify event" app_id=01DAEFT69XNG8G010ZJ0000001 container_id=01DAESEYXQNG8G010ZJ0000011 cpus= event="\"/iofs/iofs267697502/phonylsnr.sock\": CHMOD" fn_id=01DAEFTSDPNG8G010ZJ0000002 idle_timeout=30 image="docker-mint.local:5000/unzip-hotwrap:0.0.2" memory=128
time="2019-05-09T17:15:12Z" level=debug msg="fsnotify event" app_id=01DAEFT69XNG8G010ZJ0000001 container_id=01DAESEYXQNG8G010ZJ0000011 cpus= event="\"/iofs/iofs267697502/lsnr.sock\": CREATE" fn_id=01DAEFTSDPNG8G010ZJ0000002 idle_timeout=30 image="docker-mint.local:5000/unzip-hotwrap:0.0.2" memory=128
time="2019-05-09T17:15:12Z" level=info msg="starting call" action="server.handleHTTPTriggerCall)-fm" app_id=01DAEFT69XNG8G010ZJ0000001 app_name=archive call_id=01DAESEYXQNG8G010ZJ0000010 container_id=01DAESEYXQNG8G010ZJ0000011 fn_id=01DAEFTSDPNG8G010ZJ0000002 trigger_source=/unzip-hotwrap
time="2019-05-09T17:15:12Z" level=debug msg="2019/05/09 17:15:12 /usr/bin/unzip -p - \n" action="server.handleHTTPTriggerCall)-fm" app_id=01DAEFT69XNG8G010ZJ0000001 app_name=archive call_id=01DAESEYXQNG8G010ZJ0000010 fn_id=01DAEFTSDPNG8G010ZJ0000002 image="docker-mint.local:5000/unzip-hotwrap:0.0.2" trigger_source=/unzip-hotwrap user_log=true
time="2019-05-09T17:15:12Z" level=debug msg="unzip: invalid zip magic 74736574\n" action="server.handleHTTPTriggerCall)-fm" app_id=01DAEFT69XNG8G010ZJ0000001 app_name=archive call_id=01DAESEYXQNG8G010ZJ0000010 fn_id=01DAEFTSDPNG8G010ZJ0000002 image="docker-mint.local:5000/unzip-hotwrap:0.0.2" trigger_source=/unzip-hotwrap user_log=true
time="2019-05-09T17:15:12Z" level=debug msg="Got resp from UDS socket" action="server.handleHTTPTriggerCall)-fm" app_id=01DAEFT69XNG8G010ZJ0000001 app_name=archive call_id=01DAESEYXQNG8G010ZJ0000010 fn_id=01DAEFTSDPNG8G010ZJ0000002 resp="&{200 OK 200 HTTP/1.1 1 1 map[Content-Type:[text/plain; charset=utf-8] Fn-Http-Status:[500] Date:[Thu, 09 May 2019 17:15:12 GMT] Content-Length:[33]] 0xc4201807e0 33 [] false false map[] 0xc420158c00 <nil>}" trigger_source=/unzip-hotwrap
time="2019-05-09T17:15:12Z" level=debug msg="docker pause" app_id=01DAEFT69XNG8G010ZJ0000001 call_id=01DAESEYXQNG8G010ZJ0000011 container_id=01DAESEYXQNG8G010ZJ0000011 cpus= fn_id=01DAEFTSDPNG8G010ZJ0000002 idle_timeout=30 image="docker-mint.local:5000/unzip-hotwrap:0.0.2" memory=128 stack=Freeze

Given the invoke now works this is almost certainly now an issue with how I'm invoking Curl to try and send a binary (I note in the logs "unzip: invalid zip magic 74736574" so clearly something is getting messed up) - if anybody could suggest the correct syntax for that that'd be really useful.

Thanks

[fadams]

I've finally got this (sorry for replying to my own posts but I figure that somebody else just might find this useful).

So I really needed to RTFM the Curl manual https://curl.haxx.se/docs/manpage.html. My main problem above was using test.zip when I should have used @test.zip (from the --data-binary section of the manual "If you start the data with the letter @, the rest should be a filename") setting Content-Type to application/octet-stream also seems sensible, so I ended up using:

curl --header "Content-Type: application/octet-stream" --data-binary @test.zip http://$(hostname -I | awk '{print $1}'):8080/t/archive/unzip-hotwrap

which finally results in the unzipped text appearing on stdout, whew....

[rdallman]

thanks for posting the details @fadams this may end up being useful to quite a few people. glad you got everything working.

going to close since this seems resolved, except that the debugging xp can use some improvement :/