skicka - panic: no parents, but path isn't "."?

46 views
Skip to first unread message

Rasta G.

unread,
Apr 16, 2015, 2:38:23 AM4/16/15
to skicka...@googlegroups.com
Hi,

with "old" skicka I am able to list My Drive root:

xxx@xxx:~$ skicka20150403 -verbose -debug -config=/home/xxx/.skicka.config-xxx ls /
2015/04/16 08:22:30 GetFileById: root
2015/04/16 08:22:30 Running query: trashed=false and '0AHGeSBTyPxUOUk9PVA' in parents
...
xxx@xxx:~$


But with new updated skicka with local metadata cache funcionality not:

xxx@xxx:~$ skicka -verbose -debug -config=/home/xxx/.skicka.config-xxx ls /
2015/04/16 08:22:36 Read max change id 20433361
2015/04/16 08:22:37 done updating from drive 2015-04-16 08:22:37.231529694 +0200 CEST
2015/04/16 08:22:43 Done reading file cache from disk @ 2015-04-16 08:22:43.38785249 +0200 CEST
2015/04/16 08:22:43 File cache has 1753575 items
2015/04/16 08:22:43 getFileById: root
panic: no parents, but path isn't "."?

goroutine 1 [running]:
runtime.panic(0x68c5c0, 0xc25d35ebf0)
/usr/lib/go/src/pkg/runtime/panic.c:266 +0xb6
github.com/google/skicka/gdrive.getFilePath(0xc233233a40, 0x1e, 0xc233233aa0, 0x1c, 0xc2100659c0, ...)
github.com/google/skicka/gdrive.New(0xc21001fb90, 0x48, 0xc21006b160, 0x18, 0xc210065420, ...)
main.main()
/home/xxx/opt/go/src/github.com/google/skicka/skicka.go:830 +0x8bf

goroutine 4 [chan receive]:
main.func·003()
/home/xxx/opt/go/src/github.com/google/skicka/skicka.go:821 +0x3f
created by main.main
/home/xxx/opt/go/src/github.com/google/skicka/skicka.go:824 +0x80e

goroutine 5 [sleep]:
time.Sleep(0x7735940)
/usr/lib/go/src/pkg/runtime/time.goc:31 +0x31
github.com/google/skicka/gdrive.func·003()

goroutine 8 [syscall]:
runtime.goexit()
/usr/lib/go/src/pkg/runtime/proc.c:1394

goroutine 9 [IO wait]:
net.runtime_pollWait(0x7f501f844d28, 0x72, 0x0)
/usr/lib/go/src/pkg/runtime/netpoll.goc:116 +0x6a
net.(*pollDesc).Wait(0xc2100644c0, 0x72, 0x7f501f843110, 0xb)
/usr/lib/go/src/pkg/net/fd_poll_runtime.go:81 +0x34
net.(*pollDesc).WaitRead(0xc2100644c0, 0xb, 0x7f501f843110)
/usr/lib/go/src/pkg/net/fd_poll_runtime.go:86 +0x30
net.(*netFD).Read(0xc210064460, 0xc222c62000, 0x1000, 0x1000, 0x0, ...)
/usr/lib/go/src/pkg/net/fd_unix.go:204 +0x2a0
net.(*conn).Read(0xc210000a48, 0xc222c62000, 0x1000, 0x1000, 0x71eaa0, ...)
/usr/lib/go/src/pkg/net/net.go:122 +0xc5
crypto/tls.(*block).readFromUntil(0xc210073b40, 0x7f501f844e58, 0xc210000a48, 0x5, 0xc210000a48, ...)
/usr/lib/go/src/pkg/crypto/tls/conn.go:459 +0xb6
crypto/tls.(*Conn).readRecord(0xc210053a00, 0x17, 0x0, 0x8)
/usr/lib/go/src/pkg/crypto/tls/conn.go:539 +0x107
crypto/tls.(*Conn).Read(0xc210053a00, 0xc223137000, 0x1000, 0x1000, 0x0, ...)
/usr/lib/go/src/pkg/crypto/tls/conn.go:897 +0x135
bufio.(*Reader).fill(0xc223134240)
/usr/lib/go/src/pkg/bufio/bufio.go:91 +0x110
bufio.(*Reader).Peek(0xc223134240, 0x1, 0x0, 0x0, 0x0, ...)
/usr/lib/go/src/pkg/bufio/bufio.go:119 +0xcb
net/http.(*persistConn).readLoop(0xc210059600)
/usr/lib/go/src/pkg/net/http/transport.go:687 +0xb7
created by net/http.(*Transport).dialConn
/usr/lib/go/src/pkg/net/http/transport.go:528 +0x607

goroutine 10 [select]:
net/http.(*persistConn).writeLoop(0xc210059600)
/usr/lib/go/src/pkg/net/http/transport.go:791 +0x271
created by net/http.(*Transport).dialConn
/usr/lib/go/src/pkg/net/http/transport.go:529 +0x61e
xxx@xxx:~$
xxx@xxx:~$ ls -la .skicka.*
-rw------- 1 xxx xxx       886 Apr  3 11:05 .skicka.config-xxx
-rw------- 1 xxx xxx       886 Apr  3 11:25 .skicka.config-yyy
-rw------- 1 xxx xxx 314384468 Apr 16 08:33 .skicka.metadata.cache
-rw------- 1 xxx xxx       246 Apr 16 08:20 .skicka.tokencache.json
-rw------- 1 xxx xxx       246 Apr 16 08:32 .skicka.tokencache.json-xxx
-rw------- 1 xxx xxx       225 Apr  3 11:26 .skicka.tokencache.json-yyy

BTW. first metadata cache update took about 4 hours (1753575 items).

Thanks,
Rasta

Matt Pharr

unread,
Apr 17, 2015, 7:55:42 PM4/17/15
to Rasta G., skicka...@googlegroups.com
Hmm, very curious. I've tried to audit the code to figure out why this could be happening, but haven't had any luck.  I just pushed an update with some improved error logging; would you mind running it again and sending the output?  (You may want to elide some file/path names in the output if they're sensitive, etc.)

That's a very long initial metadata cache initialization (and a large file to store it all)--I'll see what can be done to improve both of those. I hope that the performance that the cache gives is worth it!

Thanks,
Matt


--
You received this message because you are subscribed to the Google Groups "skicka-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to skicka-users...@googlegroups.com.
To post to this group, send email to skicka...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/skicka-users/2dc7c74d-498f-49ae-84bf-0ce837952380%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Radek Šafránek

unread,
Apr 18, 2015, 4:45:06 PM4/18/15
to ma...@pharr.org, skicka...@googlegroups.com
Hi Matt,

skicka update:
xxx@xxx:~$ go get -u github.com/google/skicka

list:
xxx@xxx:~$ skicka -debug ls /
2015/04/18 19:52:05 Read max change id 20437844
Updating metadata cache: [--------------------------------------------------------------------------------------------------------------------------------------------------------------------] 0.00 % 2015/04/18 19:52:14 Done reading file cache from disk
Updating metadata cache: [========================================================================>-------------------------------------------------------------------------------------] 45.83 % 13m3s

memory usage (from other terminal - top):
top - 20:03:19 up 15 min,  1 user,  load average: 0.21, 0.34, 0.34
Tasks: 204 total,   1 running, 202 sleeping,   0 stopped,   1 zombie
%Cpu(s):  2.2 us,  0.5 sy,  0.0 ni, 97.3 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem:   8128880 total,  3764956 used,  4363924 free,    65296 buffers
KiB Swap:  8343548 total,        0 used,  8343548 free.  1083412 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                                                                                                                            
 3078 xxx       20   0 1717532 1.341g   4160 S   1.0 17.3   0:32.94 skicka -debug ls /     

xxx@xxx:~$ skicka -debug ls /
2015/04/18 19:52:05 Read max change id 20437844
Updating metadata cache: [--------------------------------------------------------------------------------------------------------------------------------------------------------------------] 0.00 % 2015/04/18 19:52:14 Done reading file cache from disk
Updating metadata cache: [============================================================================================================================================================] 100.00 % 44m41s
2015/04/18 20:36:48 Done updating metadata from Drive
2015/04/18 20:36:48 File cache has 1758209 items
2015/04/18 20:36:48 Writing updated file cache to disk: maxChangeId now 20932522
2015/04/18 20:36:51 /tmp/skicka.metadata603273540 -> /home/xxx/.skicka.metadata.cache: rename failed. Trying manual copy.
2015/04/18 20:36:52 Done writing new file cache to disk
2015/04/18 20:36:53 getFileById: root
panic: no parents for file &{Path:pictures_osobni_bankovnictvi FileSize:0 Id:0BwXQf59uibEgS0lwOXdfd1lldFk Md5: MimeType:application/vnd.google-apps.folder ModTime:2014-09-10 16:52:27 +0000 UTC ParentIds:[] Properties:[]} with WIP path proc-platit-kartou.jpg but parent path isn't "."?

goroutine 1 [running]:
runtime.panic(0x68c5c0, 0xc289ca1e80)
/usr/lib/go/src/pkg/runtime/panic.c:266 +0xb6
github.com/google/skicka/gdrive.getFilePath(0xc22f856cc0, 0x16, 0xc22f856d40, 0x1c, 0xc210065960, ...)
github.com/google/skicka/gdrive.New(0xc21001fb90, 0x48, 0xc21006b1a0, 0x18, 0xc210065420, ...)
main.main()
/home/xxx/opt/go/src/github.com/google/skicka/skicka.go:830 +0x8bf

goroutine 4 [chan receive]:
main.func·003()
/home/xxx/opt/go/src/github.com/google/skicka/skicka.go:821 +0x3f
created by main.main
/home/xxx/opt/go/src/github.com/google/skicka/skicka.go:824 +0x80e

goroutine 5 [sleep]:
time.Sleep(0x7735940)
/usr/lib/go/src/pkg/runtime/time.goc:31 +0x31

goroutine 8 [syscall]:
runtime.goexit()
/usr/lib/go/src/pkg/runtime/proc.c:1394

goroutine 9 [IO wait]:
net.runtime_pollWait(0x7f6d94f44b00, 0x72, 0x0)
/usr/lib/go/src/pkg/runtime/netpoll.goc:116 +0x6a
net.(*pollDesc).Wait(0xc2100644c0, 0x72, 0x7f6d94f43110, 0xb)
/usr/lib/go/src/pkg/net/fd_poll_runtime.go:81 +0x34
net.(*pollDesc).WaitRead(0xc2100644c0, 0xb, 0x7f6d94f43110)
/usr/lib/go/src/pkg/net/fd_poll_runtime.go:86 +0x30
net.(*netFD).Read(0xc210064460, 0xc222fb3000, 0x1000, 0x1000, 0x0, ...)
/usr/lib/go/src/pkg/net/fd_unix.go:204 +0x2a0
net.(*conn).Read(0xc210000a48, 0xc222fb3000, 0x1000, 0x1000, 0xb18a28, ...)
/usr/lib/go/src/pkg/net/net.go:122 +0xc5
crypto/tls.(*block).readFromUntil(0xc2100705a0, 0x7f6d94f44c30, 0xc210000a48, 0x5, 0xc210000a48, ...)
/usr/lib/go/src/pkg/crypto/tls/conn.go:459 +0xb6
crypto/tls.(*Conn).readRecord(0xc210053a00, 0x17, 0x0, 0x8)
/usr/lib/go/src/pkg/crypto/tls/conn.go:539 +0x107
crypto/tls.(*Conn).Read(0xc210053a00, 0xc222fad000, 0x1000, 0x1000, 0x0, ...)
/usr/lib/go/src/pkg/crypto/tls/conn.go:897 +0x135
bufio.(*Reader).fill(0xc222f68ba0)
/usr/lib/go/src/pkg/bufio/bufio.go:91 +0x110
bufio.(*Reader).Peek(0xc222f68ba0, 0x1, 0x0, 0x0, 0x0, ...)
/usr/lib/go/src/pkg/bufio/bufio.go:119 +0xcb
net/http.(*persistConn).readLoop(0xc210059600)
/usr/lib/go/src/pkg/net/http/transport.go:687 +0xb7
created by net/http.(*Transport).dialConn
/usr/lib/go/src/pkg/net/http/transport.go:528 +0x607

goroutine 10 [select]:
net/http.(*persistConn).writeLoop(0xc210059600)
/usr/lib/go/src/pkg/net/http/transport.go:791 +0x271
created by net/http.(*Transport).dialConn
/usr/lib/go/src/pkg/net/http/transport.go:529 +0x61e
xxx@xxx:~$ 


old skicka:
xxx@xxx:~$ skicka20150403 -debug ls /
2015/04/18 22:14:52 GetFileById: root
2015/04/18 22:14:52 Running query: trashed=false and '0AHGeSBTyPxUOUk9PVA' in parents
xxx/
xxxxxxxx/
xxxxxxxxxxxxxxxxx
xxx/
xxxxxxxx/
xxx@xxx:~$

metadata cache file size:
xxx@xxx:~$ ls -lah .skicka.metadata.cache 
-rw------- 1 xxx xxx 301M Apr 18 20:36 .skicka.metadata.cache


repeated list:

xxx@xxx:~$ skicka -debug ls /
2015/04/18 22:20:11 Read max change id 20932522
2015/04/18 22:20:12 Done updating metadata from Drive
2015/04/18 22:20:18 Done reading file cache from disk
2015/04/18 22:20:18 File cache has 1758209 items
2015/04/18 22:20:18 getFileById: root
panic: no parents for file &{Path:proof.de FileSize:0 Id:0BwXQf59uibEgczZ2ZWdROEhEeW8 Md5: MimeType:application/vnd.google-apps.folder ModTime:2014-07-23 10:37:57.908 +0000 UTC ParentIds:[] Properties:[]} with WIP path proof.xml but parent path isn't "."?

goroutine 1 [running]:
runtime.panic(0x68c5c0, 0xc25c120aa0)
/usr/lib/go/src/pkg/runtime/panic.c:266 +0xb6
github.com/google/skicka/gdrive.getFilePath(0xc24b251410, 0x9, 0xc24b253520, 0x1c, 0xc210065960, ...)
github.com/google/skicka/gdrive.New(0xc21001fb90, 0x48, 0xc21006b1a0, 0x18, 0xc210065420, ...)
main.main()
/home/xxx/opt/go/src/github.com/google/skicka/skicka.go:830 +0x8bf

goroutine 4 [chan receive]:
main.func·003()
/home/xxx/opt/go/src/github.com/google/skicka/skicka.go:821 +0x3f
created by main.main
/home/xxx/opt/go/src/github.com/google/skicka/skicka.go:824 +0x80e

goroutine 5 [sleep]:
time.Sleep(0x7735940)
/usr/lib/go/src/pkg/runtime/time.goc:31 +0x31

goroutine 8 [syscall]:
runtime.goexit()
/usr/lib/go/src/pkg/runtime/proc.c:1394

goroutine 9 [IO wait]:
net.runtime_pollWait(0x7f0e62601b00, 0x72, 0x0)
/usr/lib/go/src/pkg/runtime/netpoll.goc:116 +0x6a
net.(*pollDesc).Wait(0xc2100644c0, 0x72, 0x7f0e62600110, 0xb)
/usr/lib/go/src/pkg/net/fd_poll_runtime.go:81 +0x34
net.(*pollDesc).WaitRead(0xc2100644c0, 0xb, 0x7f0e62600110)
/usr/lib/go/src/pkg/net/fd_poll_runtime.go:86 +0x30
net.(*netFD).Read(0xc210064460, 0xc228fb0000, 0x1000, 0x1000, 0x0, ...)
/usr/lib/go/src/pkg/net/fd_unix.go:204 +0x2a0
net.(*conn).Read(0xc210000a48, 0xc228fb0000, 0x1000, 0x1000, 0x71eaa0, ...)
/usr/lib/go/src/pkg/net/net.go:122 +0xc5
crypto/tls.(*block).readFromUntil(0xc210074ab0, 0x7f0e62601c30, 0xc210000a48, 0x5, 0xc210000a48, ...)
/usr/lib/go/src/pkg/crypto/tls/conn.go:459 +0xb6
crypto/tls.(*Conn).readRecord(0xc210054a00, 0x17, 0x0, 0x8)
/usr/lib/go/src/pkg/crypto/tls/conn.go:539 +0x107
crypto/tls.(*Conn).Read(0xc210054a00, 0xc223dbd000, 0x1000, 0x1000, 0x0, ...)
/usr/lib/go/src/pkg/crypto/tls/conn.go:897 +0x135
bufio.(*Reader).fill(0xc223d96540)
/usr/lib/go/src/pkg/bufio/bufio.go:91 +0x110
bufio.(*Reader).Peek(0xc223d96540, 0x1, 0x0, 0x0, 0x0, ...)
/usr/lib/go/src/pkg/bufio/bufio.go:119 +0xcb
net/http.(*persistConn).readLoop(0xc21005a600)
/usr/lib/go/src/pkg/net/http/transport.go:687 +0xb7
created by net/http.(*Transport).dialConn
/usr/lib/go/src/pkg/net/http/transport.go:528 +0x607

goroutine 10 [select]:
net/http.(*persistConn).writeLoop(0xc21005a600)
/usr/lib/go/src/pkg/net/http/transport.go:791 +0x271
created by net/http.(*Transport).dialConn
/usr/lib/go/src/pkg/net/http/transport.go:529 +0x61e
xxx@xxx:~$ 


and again:
xxx@xxx:~$ skicka -debug ls /
2015/04/18 22:22:22 Read max change id 20932522
2015/04/18 22:22:23 Done updating metadata from Drive
2015/04/18 22:22:28 Done reading file cache from disk
2015/04/18 22:22:28 File cache has 1758209 items
2015/04/18 22:22:28 getFileById: root
panic: no parents for file &{Path:pictures_osobni_bankovnictvi FileSize:0 Id:0BwXQf59uibEgS0lwOXdfd1lldFk Md5: MimeType:application/vnd.google-apps.folder ModTime:2014-09-10 16:52:27 +0000 UTC ParentIds:[] Properties:[]} with WIP path maestro_141x198.jpg but parent path isn't "."?

goroutine 1 [running]:
runtime.panic(0x68c5c0, 0xc2651d3410)
/usr/lib/go/src/pkg/runtime/panic.c:266 +0xb6
...

and again:
xxx@xxx:~$ skicka -debug ls /
2015/04/18 22:23:40 Read max change id 20932522
2015/04/18 22:23:40 Done updating metadata from Drive
2015/04/18 22:23:46 Done reading file cache from disk
2015/04/18 22:23:46 File cache has 1758209 items
2015/04/18 22:23:46 getFileById: root
panic: no parents for file &{Path:pictures_osobni_bankovnictvi FileSize:0 Id:0BwXQf59uibEgS0lwOXdfd1lldFk Md5: MimeType:application/vnd.google-apps.folder ModTime:2014-09-10 16:52:27 +0000 UTC ParentIds:[] Properties:[]} with WIP path proc-platit-kartou.jpg but parent path isn't "."?

goroutine 1 [running]:
runtime.panic(0x68c5c0, 0xc25e8cc0e0)
/usr/lib/go/src/pkg/runtime/panic.c:266 +0xb6
....

xxx@xxx:~$ skicka -debug ls /
2015/04/18 22:25:43 Read max change id 20932522
2015/04/18 22:25:44 Done updating metadata from Drive
2015/04/18 22:25:50 Done reading file cache from disk
2015/04/18 22:25:50 File cache has 1758209 items
2015/04/18 22:25:50 getFileById: root
panic: no parents for file &{Path:psd FileSize:0 Id:0B9ZjO8Alt1XyUGxUOFZseDZUTlE Md5: MimeType:application/vnd.google-apps.folder ModTime:2015-04-02 09:15:56.651 +0000 UTC ParentIds:[] Properties:[]} with WIP path draft but parent path isn't "."?

goroutine 1 [running]:

and again with only few top output lines:

xxx@xxx:~$ skicka -debug ls / 2>&1 | head -n 7
2015/04/18 22:27:07 Read max change id 20932522
2015/04/18 22:27:08 Done updating metadata from Drive
2015/04/18 22:27:14 Done reading file cache from disk
2015/04/18 22:27:14 File cache has 1758209 items
2015/04/18 22:27:14 getFileById: root
panic: no parents for file &{Path:_production_ FileSize:0 Id:0BwXQf59uibEgYnpHVy1nRk9DZm8 Md5: MimeType:application/vnd.google-apps.folder ModTime:2014-09-11 03:02:48 +0000 UTC ParentIds:[] Properties:[]} with WIP path __common__ but parent path isn't "."?

xxx@xxx:~$ 
xxx@xxx~$ skicka -debug ls / 2>&1 | head -n 7
2015/04/18 22:27:21 Read max change id 20932522
2015/04/18 22:27:22 Done updating metadata from Drive
2015/04/18 22:27:28 Done reading file cache from disk
2015/04/18 22:27:28 File cache has 1758209 items
2015/04/18 22:27:28 getFileById: root
panic: no parents for file &{Path:proof.sk FileSize:0 Id:0BwXQf59uibEgQnd1WDZyNm5YdWs Md5: MimeType:application/vnd.google-apps.folder ModTime:2014-07-23 10:37:57.908 +0000 UTC ParentIds:[] Properties:[]} with WIP path proof.msi but parent path isn't "."?

xxx@xxx:~$ skicka -debug ls / 2>&1 | head -n 7
2015/04/18 22:27:36 Read max change id 20932522
2015/04/18 22:27:36 Done updating metadata from Drive
2015/04/18 22:27:42 Done reading file cache from disk
2015/04/18 22:27:42 File cache has 1758209 items
2015/04/18 22:27:42 getFileById: root
panic: no parents for file &{Path:proof.en FileSize:0 Id:0BwXQf59uibEgMHM0SF9JNDBGR2M Md5: MimeType:application/vnd.google-apps.folder ModTime:2014-07-23 10:37:57.908 +0000 UTC ParentIds:[] Properties:[]} with WIP path proof.xml but parent path isn't "."?

xxx@xxx:~$ skicka -debug ls / 2>&1 | head -n 7
2015/04/18 22:27:51 Read max change id 20932522
2015/04/18 22:27:52 Done updating metadata from Drive
2015/04/18 22:27:58 Done reading file cache from disk
2015/04/18 22:27:58 File cache has 1758209 items
2015/04/18 22:27:58 getFileById: root
panic: no parents for file &{Path:pictures_osobni_bankovnictvi FileSize:0 Id:0BwXQf59uibEgS0lwOXdfd1lldFk Md5: MimeType:application/vnd.google-apps.folder ModTime:2014-09-10 16:52:27 +0000 UTC ParentIds:[] Properties:[]} with WIP path proc-platit-kartou.jpg but parent path isn't "."? 

Thanks,
Rasta

Reply all
Reply to author
Forward
0 new messages