fetching node's IP address..
Process pid is 108477
ip address on interface 'lo' is 127.0.0.1
cluster settings:
[tid:108477][register_peer_log():243] assigning peer (ip: 127.0.0.1 pid: 0) to log id 0
--- node 0 - ip:127.0.0.1
Connecting to KernFS instance 0 [ip: 127.0.0.1]
[Local-Client] Creating connection (pid:108477, app_type:0, status:pending) to 127.0.0.1:12345 on sockfd 0
[Local-Client] Creating connection (pid:108477, app_type:1, status:pending) to 127.0.0.1:12345 on sockfd 1
In thread
In thread
[Local-Client] Creating connection (pid:108477, app_type:2, status:pending) to 127.0.0.1:12345 on sockfd 2
[tid:108477][init_rpc():148] awaiting remote KernFS connections
In thread
SEND --> MSG_INIT [pid 0|108477]
SEND --> MSG_INIT [pid 2|108477]
SEND --> MSG_INIT [pid 1|108477]
RECV <-- MSG_SHM [paths: /shm_recv_2|/shm_send_2]
RECV <-- MSG_SHM [paths: /shm_recv_0|/shm_send_0]
[tid:108479][add_peer_socket():63] found socket 1
[tid:108480][add_peer_socket():63] found socket 2
[tid:108479][_find_peer():176] trying to find peer with ip 127.0.0.1 and pid 0 (peer count: 1 | sock count: 0)
[tid:108479][_find_peer():206] peer[0]: ip 127.0.0.1 pid 0
[add_peer_socket():97] Established connection with 127.0.0.1 on sock:1 of type:1 and peer:0x7f77079fc000
start shmem_poll_loop for sockfd 1
[tid:108480][_find_peer():176] trying to find peer with ip 127.0.0.1 and pid 0 (peer count: 1 | sock count: 1)
[tid:108480][_find_peer():191] sockfd[0]: ip 127.0.0.1 pid 0
[add_peer_socket():97] Established connection with 127.0.0.1 on sock:2 of type:2 and peer:0x7f77079fc000
start shmem_poll_loop for sockfd 2
RECV <-- MSG_SHM [paths: /shm_recv_1|/shm_send_1]
[tid:108478][add_peer_socket():63] found socket 0
[tid:108478][_find_peer():176] trying to find peer with ip 127.0.0.1 and pid 0 (peer count: 1 | sock count: 2)
[tid:108478][_find_peer():191] sockfd[0]: ip 127.0.0.1 pid 0
[add_peer_socket():97] Established connection with 127.0.0.1 on sock:0 of type:0 and peer:0x7f77079fc000
start shmem_poll_loop for sockfd 0
[tid:108477][rpc_bootstrap():907] peer send: |bootstrap |108477
[tid:108478][signal_callback():1412] received rpc with body: |bootstrap |1 on sockfd 0
[signal_callback():1425] Assigned LibFS ID=1
MLFS cluster initialized
[tid:108477][init_log():148] end of the log 7dd600
init log dev 1 start_blk 7984641 end 8246784
src/filesystem/fs.c:read_ondisk_inode:598: read_ondisk_inode++: inum: 1
src/filesystem/fs.c:__read_ondisk_inode:580: kvsdip and dip differs!!!
src/filesystem/fs.c:__read_ondisk_inode:582: kvsdip++
src/kvs/main.c:dump_dinode:214: dump_dinode++
src/kvs/main.c:dump_dinode:226: dinode->itype: 0 (unknown)
src/kvs/main.c:dump_dinode:229: dinode->nlink: 0
src/kvs/main.c:dump_dinode:230: dinode->size: 0
src/kvs/main.c:dump_dinode:231: dump_dinode--
src/filesystem/fs.c:__read_ondisk_inode:584: kvsdip--
src/filesystem/fs.c:__read_ondisk_inode:586: dip++
src/kvs/main.c:dump_dinode:214: dump_dinode++
src/kvs/main.c:dump_dinode:217: dinode->itype: T_DIR
src/kvs/main.c:dump_dinode:229: dinode->nlink: 1
src/kvs/main.c:dump_dinode:230: dinode->size: 96
src/kvs/main.c:dump_dinode:231: dump_dinode--
src/filesystem/fs.c:__read_ondisk_inode:588: dip--
src/filesystem/fs.c:read_ondisk_inode:600: read_ondisk_inode--: inum: 1
[tid:108477][ialloc():630] get inode - inum 1
[tid:108477][init_fs():463] LibFS is initialized on dev 1
src/kvs/main.c:lightfs_db_env_create:47: lightfs_db_env_create:47
src/kvs/main.c:lightfs_db_create:170: lightfs_db_create:170
src/kvs/main.c:init_kvs:206: DB Created!
dump_restore: restoring "m:2:1"
dump_restore: db_put() returned 0
dump_restore: restoring "m:10000:2"
dump_restore: db_put() returned 0
dump_restore: restoring "m:10001:3"
dump_restore: db_put() returned 0
EOF
[tid:108477][mlfs_posix_mkdir():414] [POSIX] mkdir(/mlfs/1)
src/filesystem/dirent.c:nameiparent:412: nameiparent: path: "/mlfs/1", parent_path: "/mlfs"
[tid:108477][namex():275] namex: path /mlfs/1, parent 1, name 1
src/filesystem/dirent.c:namex:300: namex: loop: path: "1", name: "mlfs", ip->inum: 1
[tid:108477][dir_lookup():50] dir_lookup: de_cache miss for dir 1, name mlfs
src/filesystem/dirent.c:dir_lookup:52: dir_inode->n_de_cache_entry: 0
src/filesystem/dirent.c:dir_lookup:53: dir_inode->size: 96
[tid:108477][dir_lookup():62] dir_lookup: starting search for name mlfs (dirs: cached 2 total 3)
[tid:108477][readi():2173] read stats: inode[inum 1 isize 96] size_small 32 size_prepended 0 size_aligned 0 size_appended 0
[tid:108477][do_unaligned_read():1283] unaligned read for : inum 1, offset 64, io_size 32 type: local
[tid:108477][bmap():868] mlfs_ext_get_blocks: start
[tid:108477][mlfs_ext_binsearch():714]   -> 0:6abb:[0]1
[tid:108477][bmap():870] mlfs_ext_get_blocks: ret 1
[tid:108477][readi():2215] finishing read. iodone: 32
[tid:108477][iget():789] allocate new inode by iget 2
src/filesystem/fs.c:read_ondisk_inode:598: read_ondisk_inode++: inum: 2
src/kvs/main.c:read_kvs_dinode:246: read_kvs_dinode: KEY: "m:1:mlfs"
src/kvs/main.c:read_kvs_dinode:255: db_get() returned -30989
src/filesystem/fs.c:__read_ondisk_inode:586: dip++
src/kvs/main.c:dump_dinode:214: dump_dinode++
src/kvs/main.c:dump_dinode:217: dinode->itype: T_DIR
src/kvs/main.c:dump_dinode:229: dinode->nlink: 1
src/kvs/main.c:dump_dinode:230: dinode->size: 64
src/kvs/main.c:dump_dinode:231: dump_dinode--
src/filesystem/fs.c:__read_ondisk_inode:588: dip--
src/filesystem/fs.c:read_ondisk_inode:600: read_ondisk_inode--: inum: 2
[tid:108477][ialloc():630] get inode - inum 2
src/filesystem/dirent.c:namex:300: namex: loop: path: "", name: "1", ip->inum: 2
src/filesystem/dirent.c:namex:310: namex: 310: returning ip
[tid:108477][dir_lookup():50] dir_lookup: de_cache miss for dir 2, name 1
src/filesystem/dirent.c:dir_lookup:52: dir_inode->n_de_cache_entry: 0
src/filesystem/dirent.c:dir_lookup:53: dir_inode->size: 64
[tid:108477][dir_lookup():57] not found w/ full de cache - skipping iteration
[tid:108477][icreate():684] finding empty inode number in slice(start:10000 size:300000)
[tid:108477][icreate():688] creating inode with inum 10000
src/filesystem/fs.c:read_ondisk_inode:598: read_ondisk_inode++: inum: 10000
src/kvs/main.c:read_kvs_dinode:246: read_kvs_dinode: KEY: "m:2:1"
data->data: ""
src/kvs/main.c:read_kvs_dinode:255: db_get() returned 256
src/kvs/main.c:read_kvs_dinode:258: KVS hit!
src/kvs/main.c:dump_dinode:214: dump_dinode++
src/kvs/main.c:dump_dinode:217: dinode->itype: T_DIR
src/kvs/main.c:dump_dinode:229: dinode->nlink: 1
src/kvs/main.c:dump_dinode:230: dinode->size: 64
src/kvs/main.c:dump_dinode:231: dump_dinode--
src/filesystem/fs.c:__read_ondisk_inode:580: kvsdip and dip differs!!!
src/filesystem/fs.c:__read_ondisk_inode:582: kvsdip++
src/kvs/main.c:dump_dinode:214: dump_dinode++
src/kvs/main.c:dump_dinode:217: dinode->itype: T_DIR
src/kvs/main.c:dump_dinode:229: dinode->nlink: 1
src/kvs/main.c:dump_dinode:230: dinode->size: 64
src/kvs/main.c:dump_dinode:231: dump_dinode--
src/filesystem/fs.c:__read_ondisk_inode:584: kvsdip--
src/filesystem/fs.c:__read_ondisk_inode:586: dip++
src/kvs/main.c:dump_dinode:214: dump_dinode++
src/kvs/main.c:dump_dinode:226: dinode->itype: 0 (unknown)
src/kvs/main.c:dump_dinode:229: dinode->nlink: 0
src/kvs/main.c:dump_dinode:230: dinode->size: 0
src/kvs/main.c:dump_dinode:231: dump_dinode--
src/filesystem/fs.c:__read_ondisk_inode:588: dip--
src/filesystem/fs.c:read_ondisk_inode:600: read_ondisk_inode--: inum: 10000
[tid:108477][ialloc():630] get inode - inum 10000
[tid:108477][add_to_loghdr():1343] add_to_loghdr [INODE_CREATE] inum 10000
[tid:108477][mlfs_object_create():494] create /mlfs/1 - inum 10000
[tid:108477][add_to_log():2233] add to log: inum 10000 offset 0 size 64
[tid:108477][add_to_log():2245] adding to loghdr
[tid:108477][add_to_loghdr():1343] add_to_loghdr [DIR_ADD] inum 10000
[tid:108477][add_to_log():2250] add to loghdr done
[tid:108477][add_to_log():2252] DEBUG off+size 64 ip->size 0
[tid:108477][add_to_log():2255] DEBUG setting ip->size to 64
[tid:108477][add_to_loghdr():1343] add_to_loghdr [INODE_UDPATE] inum 2
[tid:108477][dir_add_entry():259] adding new dirent to dir inode 2: 1 ~ 10000 at offset 64
[tid:108477][add_to_log():2233] add to log: inum 2 offset 64 size 32
[tid:108477][add_to_log():2245] adding to loghdr
[tid:108477][add_to_loghdr():1343] add_to_loghdr [DIR_ADD] inum 2
[tid:108477][add_to_log():2250] add to loghdr done
[tid:108477][add_to_log():2252] DEBUG off+size 96 ip->size 64
[tid:108477][add_to_log():2255] DEBUG setting ip->size to 96
src/log/log.c:dump_loghdr:1048:
src/log/log.c:dump_loghdr:1049: loghdr->n: 4
src/log/log.c:dump_loghdr:1051: loghdr->type[0]: L_TYPE_INODE_CREATE
src/log/log.c:dump_loghdr:1051: loghdr->type[1]: L_TYPE_DIR_ADD
src/log/log.c:dump_loghdr:1051: loghdr->type[2]: L_TYPE_INODE_UPDATE
src/log/log.c:dump_loghdr:1051: loghdr->type[3]: L_TYPE_DIR_ADD
src/log/log.c:dump_loghdr:1054: loghdr->inode_no[0]: 10000
src/log/log.c:dump_loghdr:1054: loghdr->inode_no[1]: 10000
src/log/log.c:dump_loghdr:1054: loghdr->inode_no[2]: 2
src/log/log.c:dump_loghdr:1054: loghdr->inode_no[3]: 2
src/log/log.c:dump_loghdr:1057: loghdr->data[0]: 0
src/log/log.c:dump_loghdr:1057: loghdr->data[1]: 0
src/log/log.c:dump_loghdr:1057: loghdr->data[2]: 0
src/log/log.c:dump_loghdr:1057: loghdr->data[3]: 64
src/log/log.c:dump_loghdr:1060: loghdr->length[0]: 256
src/log/log.c:dump_loghdr:1060: loghdr->length[1]: 64
src/log/log.c:dump_loghdr:1060: loghdr->length[2]: 256
src/log/log.c:dump_loghdr:1060: loghdr->length[3]: 32
src/log/log.c:dump_loghdr:1063: loghdr->blocks[0]: 0
src/log/log.c:dump_loghdr:1063: loghdr->blocks[1]: 0
src/log/log.c:dump_loghdr:1063: loghdr->blocks[2]: 0
src/log/log.c:dump_loghdr:1063: loghdr->blocks[3]: 0
src/log/log.c:dump_loghdr:1065: loghdr->nr_log_blocks: 0
src/log/log.c:dump_loghdr:1067: loghdr->inuse: 0
src/log/log.c:dump_loghdr:1068:
src/log/log.c:dump_loghdr:1044:
previous_loghdr is NULL

[tid:108477][commit_log():1188] pid 108477 [commit] log block 7984641 nr_log_blocks 5
[tid:108477][commit_log():1190] pid 108477 [commit] current header 7984641 next header 7984646
[tid:108477][persist_log_inode():664] inum 10000 offset 0 @ blockno 79d602
[tid:108477][persist_log_file():813] inum 10000 offset 0 @ blockno 79d603 (partial io_size=64)
[tid:108477][persist_log_inode():664] inum 2 offset 0 @ blockno 79d604
[tid:108477][persist_log_file():813] inum 2 offset 64 @ blockno 79d605 (partial io_size=32)
[tid:108477][persist_log_header():482] pid 108477 [log header] inuse 8121 blkno 7984641 next_hdr_blockno 7984646
src/filesystem/fs.c:write_kvs_dinode:1106: KEY: "m:2:1"
src/filesystem/fs.c:write_kvs_dinode:1107: VAL: 256 bytes
src/kvs/main.c:dump_dinode:214: dump_dinode++
src/kvs/main.c:dump_dinode:217: dinode->itype: T_DIR
src/kvs/main.c:dump_dinode:229: dinode->nlink: 1
src/kvs/main.c:dump_dinode:230: dinode->size: 64
src/kvs/main.c:dump_dinode:231: dump_dinode--
src/filesystem/fs.c:write_kvs_dinode:1119: db_put() returned 0
[tid:108477][mlfs_posix_open():107] [POSIX] open(/mlfs/1) O_CREAT:0
src/filesystem/dirent.c:namei:360: namei: path: "/mlfs/1"
[tid:108477][mlfs_file_alloc():73] creating fd: 0 | ref: 1
[tid:108477][mlfs_posix_open():154] open file /mlfs/1 inum 10000 fd 0
[tid:108477][mlfs_posix_open():159] directory file inum 10000
[tid:108477][mlfs_posix_fsync():758] [POSIX] fsync(fd=1000000)
fsync() returned 0: No such device
[tid:108477][shutdown_log():196] Shutting down log
[tid:108477][shutdown_log():236] [L] Digesting remaining log data
[set_digesting():94] set log digesting state
[tid:108477][make_digest_request_sync():1636] sanity check: n_digest (local) 1 n_digest (remote) 1
[make_digest_request_sync():1668] |digest |1|1|1|7984641|7984641|0
[tid:108477][rpc_forward_msg():894] peer send: |digest |1|1|1|7984641|7984641|0
[tid:108479][signal_callback():1412] received rpc with body: |complete |1|1|1|7984646|0|0| on sockfd 1
[signal_callback():1484] peer recv: |complete |1|1|1|7984646|0|0|
[handle_digest_response():1703] |complete |1|1|1|7984646|0|0|
[tid:108479][handle_digest_response():1708] digest is done correctly
[tid:108479][handle_digest_response():1709] -----------------------------------
[tid:108479][handle_digest_response():1716] g_fs_log->start_blk 79d601, next_hdr_of_digested_hdr 79d606
[tid:108479][handle_digest_response():1746] clear digesting state for log
[clear_digesting():108] clear log digesting state
[tid:108477][wait_on_peer_digesting():235] waiting till peer finishes digesting